From 5883ea509d290fab292d52ed2cce6195719f54a5 Mon Sep 17 00:00:00 2001 From: npeter83 Date: Thu, 17 Sep 2026 02:42:12 +0200 Subject: [PATCH] =?UTF-8?q?feat:=20Settings=20=E2=86=92=20Diagnostics,=20a?= =?UTF-8?q?=20consented=20log=20level=20and=20the=20tab's=20own=20log?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A user can raise their diagnostics level to Részletes (DEBUG) or Teljes (TRACE) for 24 hours from a new Settings tab, after a consent box that says what is recorded, that the server keeps it and for how long (the instance's own retention), and that it lapses. Alap is the base and needs no consent. - users.diagnostics_level/_until (migration 0087), written only by PUT /api/me/diagnostics, which computes the expiry itself; the demo account cannot raise it. /api/me reports the level in force. - The server logs an elevated user's requests at that level and stores every line of them (logs.LevelGate on the stdout handler and the sink; the root is lowered only while an elevation is active). Teljes adds the redacted query string to the request line. - POST /api/diagnostics/events stores the browser's log as source=web rows: account from the session, body capped while streaming, events/attrs capped, re-redacted, events under the consented level dropped, timestamps clamped, 30 batches a minute, 409 once the level lapsed. - lib/diagnostics.ts applies the level to the tab and streams only what happens after consent, in batches, never its own request lines, with a keepalive flush on pagehide; stops on lapse (its own timer), on withdrawal and on 409. - Detail hooks at DEBUG: which control was clicked (test id, icon, app copy in English — never user text, input values or a link's query), visibility/bfcache/resize, filter changes (lib/filterLog.ts; typed search only at TRACE), player events (lib/mediaLog.ts; media errors are warnings at every level). Offline/online at the base level. - "Saját napló" viewer: live, newest first, level groups with counts, search, row details, copy the filtered events as JSON lines, clear. - Privacy policy and Terms exist in Hungarian and English (a contract test holds both languages to the same sections); the policy now describes the server logs and diagnostic logging, self-service deletion and password sign-in. Fixed on the way: - A sync auth dependency ran logs.set_user on a copied context, so the account never reached a handler's own log lines (measured); a per-request mutable scope carries it now. - The Settings tab rail left a phone no room (clipped labels, buttons over text): below `sm` it is a scrolling row above the content. - PUT /api/me/preferences took a bare dict body; it is a Pydantic model now. --- CLAUDE.md | 4 +- .../versions/0087_users_diagnostics_level.py | 31 ++ backend/app/README.md | 6 +- backend/app/auth.py | 6 +- backend/app/diagnostics.py | 61 ++++ backend/app/logs.py | 150 +++++++- backend/app/logsink.py | 7 +- backend/app/main.py | 2 + backend/app/models.py | 6 + backend/app/routes/diagnostics.py | 135 +++++++ backend/app/routes/me.py | 42 ++- backend/tests/test_demo_refusal_detail.py | 20 +- backend/tests/test_diagnostics.py | 340 ++++++++++++++++++ frontend/src/App.tsx | 9 + .../DiagnosticsSettings.dom.test.tsx | 130 +++++++ .../src/components/DiagnosticsSettings.tsx | 159 ++++++++ .../src/components/FeedFiltersProvider.tsx | 2 + frontend/src/components/LibraryPlayer.tsx | 15 +- .../src/components/MyLogViewer.dom.test.tsx | 95 +++++ frontend/src/components/MyLogViewer.tsx | 229 ++++++++++++ frontend/src/components/PlexPlayer.tsx | 20 ++ frontend/src/components/PlexProvider.tsx | 7 + frontend/src/components/SettingsPanel.tsx | 14 +- frontend/src/components/legal/LegalLayout.tsx | 77 ++-- .../src/components/legal/PrivacyPolicy.tsx | 255 +++++++++++-- frontend/src/components/legal/Terms.tsx | 109 +++++- .../legal/legalBodies.contract.dom.test.tsx | 36 ++ frontend/src/components/legal/useHungarian.ts | 7 + frontend/src/components/ui/Tabs.tsx | 13 +- frontend/src/i18n/appCopy.dom.test.ts | 26 ++ frontend/src/i18n/appCopy.ts | 43 +++ frontend/src/i18n/locales/en/legal.json | 7 + frontend/src/i18n/locales/en/settings.json | 59 ++- frontend/src/i18n/locales/hu/legal.json | 7 + frontend/src/i18n/locales/hu/settings.json | 59 ++- frontend/src/lib/api.ts | 4 + frontend/src/lib/api/account.ts | 3 + frontend/src/lib/api/diagnostics.ts | 35 ++ frontend/src/lib/api/facade.test.ts | 1 + frontend/src/lib/detailLog.dom.test.ts | 71 ++++ frontend/src/lib/diagnostics.dom.test.ts | 147 ++++++++ frontend/src/lib/diagnostics.ts | 123 +++++++ frontend/src/lib/filterLog.ts | 21 ++ frontend/src/lib/log.ts | 33 +- frontend/src/lib/logHooks.dom.test.ts | 75 +++- frontend/src/lib/logHooks.ts | 111 +++++- frontend/src/lib/mediaLog.ts | 90 +++++ frontend/src/lib/playerModalHooks.ts | 7 + frontend/src/main.tsx | 3 +- 49 files changed, 2790 insertions(+), 122 deletions(-) create mode 100644 backend/alembic/versions/0087_users_diagnostics_level.py create mode 100644 backend/app/diagnostics.py create mode 100644 backend/app/routes/diagnostics.py create mode 100644 backend/tests/test_diagnostics.py create mode 100644 frontend/src/components/DiagnosticsSettings.dom.test.tsx create mode 100644 frontend/src/components/DiagnosticsSettings.tsx create mode 100644 frontend/src/components/MyLogViewer.dom.test.tsx create mode 100644 frontend/src/components/MyLogViewer.tsx create mode 100644 frontend/src/components/legal/legalBodies.contract.dom.test.tsx create mode 100644 frontend/src/components/legal/useHungarian.ts create mode 100644 frontend/src/i18n/appCopy.dom.test.ts create mode 100644 frontend/src/i18n/appCopy.ts create mode 100644 frontend/src/i18n/locales/en/legal.json create mode 100644 frontend/src/i18n/locales/hu/legal.json create mode 100644 frontend/src/lib/api/diagnostics.ts create mode 100644 frontend/src/lib/detailLog.dom.test.ts create mode 100644 frontend/src/lib/diagnostics.dom.test.ts create mode 100644 frontend/src/lib/diagnostics.ts create mode 100644 frontend/src/lib/filterLog.ts create mode 100644 frontend/src/lib/mediaLog.ts diff --git a/CLAUDE.md b/CLAUDE.md index 83604e3a..70bc60c6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -58,7 +58,7 @@ how it gets built. Concretely: `routes/*` (HTTP only: validation, auth-dependency, serialization) → domain packages `sync/`, `plex/`, `downloads/`, `youtube/` (shared by routes + scheduler + worker) → flat core (`auth`, `quota`, `sysconfig`, `state`, `audit`, `notifications`, `userscope`, `realtime`, `ratelimit`, `progress`, -`security`, `logs`, `logsink`) → `models/db/config`. **Dependency direction is one-way: core never imports routes.** +`security`, `logs`, `logsink`, `diagnostics`) → `models/db/config`. **Dependency direction is one-way: core never imports routes.** Frontend: `main.tsx` provider tree → `App.tsx` shell → `moduleRegistry` route-chunks → module components → the **platform layer `components/ui/`** (domain-free primitives: the popover engine and its menus, `Modal`/`Overlay`, `Button`/`form`, `DataTable`/`VirtualGrid`, `QueryState`, …). That @@ -96,7 +96,7 @@ CQRS, a repository/DI framework, a router library, a generic CRUD-router factory | FE loading/empty/error | `QueryState` / `StateMessage` | ad-hoc conditionals | | FE failed write | `meta.failTitle`, else `notifyActionError(err, title)` | a bare `catch {}` or `notify()` with no error attached | | FE network call | `req`/`uploadReq`/`beacon`, or `lib/http.ts` `send` (public pages) | a bare `fetch`/`XMLHttpRequest`/`WebSocket` (lint-enforced) | -| FE diagnostics | `lib/log.ts` (`log.info("event.code", msg, attrs)`) | `console.*` (lint-enforced) | +| FE diagnostics | `lib/log.ts` (`log.info("event.code", msg, attrs)`); a filter change → `lib/filterLog.ts`, a player → `lib/mediaLog.ts` | `console.*` (lint-enforced); a value only a higher level may carry, logged unguarded | ## House rules that bite (learned from real bugs) diff --git a/backend/alembic/versions/0087_users_diagnostics_level.py b/backend/alembic/versions/0087_users_diagnostics_level.py new file mode 100644 index 00000000..ca550729 --- /dev/null +++ b/backend/alembic/versions/0087_users_diagnostics_level.py @@ -0,0 +1,31 @@ +"""add users.diagnostics_level + diagnostics_until — a user's consented diagnostics level (E22 S5) + +Revision ID: 0087_users_diagnostics_level +Revises: 0086_log_events +Create Date: 2026-09-17 + +Both NULL = the base level (Alap). A raised level is ALWAYS paired with its expiry, computed by the +server at consent time (`app/diagnostics.py`), so no client can ask for a level that never ends. +Columns rather than `users.preferences`: that JSON is written wholesale by the client, and a consent +with a lifetime must not be something a client can write. +""" + +import sqlalchemy as sa +from alembic import op + +revision: str = "0087_users_diagnostics_level" +down_revision: str | None = "0086_log_events" +branch_labels: str | None = None +depends_on: str | None = None + + +def upgrade() -> None: + op.add_column("users", sa.Column("diagnostics_level", sa.String(8), nullable=True)) + op.add_column( + "users", sa.Column("diagnostics_until", sa.DateTime(timezone=True), nullable=True) + ) + + +def downgrade() -> None: + op.drop_column("users", "diagnostics_until") + op.drop_column("users", "diagnostics_level") diff --git a/backend/app/README.md b/backend/app/README.md index bb8f8585..ec04ecc2 100644 --- a/backend/app/README.md +++ b/backend/app/README.md @@ -21,9 +21,9 @@ Three layers, by *who* runs the code — not by feature: 3. **Flat `app/*.py` core modules — cross-cutting primitives.** `auth`, `sysconfig`, `quota`, `audit`, `notifications`, `userscope`, `realtime`, `ratelimit`, `progress`, `logs` (the one logging - configuration) and `logsink` (its `log_events` table), … are single-file primitives many - layers import. They depend on nothing above them (a core module must never import a `routes/…` - module). + configuration), `logsink` (its `log_events` table) and `diagnostics` (a user's consented log + level), … are single-file primitives many layers import. They depend on nothing above them (a core + module must never import a `routes/…` module). **Extraction trigger: the SECOND consumer.** Keep new logic inline in its first caller. The moment a *second* caller needs it (a worker as well as a route; a scheduler as well as a route), extract it down diff --git a/backend/app/auth.py b/backend/app/auth.py index 37515c70..26384175 100644 --- a/backend/app/auth.py +++ b/backend/app/auth.py @@ -6,6 +6,7 @@ from sqlalchemy import delete, func, select from sqlalchemy.orm import Session from starlette.requests import HTTPConnection +from app import diagnostics from app import email as email_mod from app import logs from app import mailtext @@ -355,8 +356,9 @@ def _session_user(request: Request, db: Session, user_id: int | None, is_default # Attribute this request's log lines to the account (E22). Here, not in the request middleware: # this is the one place a session becomes an account, and the middleware runs outside both the # session middleware and this task's context. `request.state` is shared across middleware layers - # (it lives on the ASGI scope), so the access-log line can read it back. - logs.set_user(user.id) + # (it lives on the ASGI scope), so the access-log line can read it back. The user's consented + # diagnostics level rides along: their requests are logged — and stored — in that detail (S5). + logs.set_user(user.id, diagnostics.effective_level(user), user.diagnostics_until) request.state.user_id = user.id return user diff --git a/backend/app/diagnostics.py b/backend/app/diagnostics.py new file mode 100644 index 00000000..89a78e9e --- /dev/null +++ b/backend/app/diagnostics.py @@ -0,0 +1,61 @@ +"""A user's diagnostics level (E22 S5): what they consented to, and for how long. + +Three levels, named in the UI Alap / Részletes / Teljes: + + * INFO — the base, for everyone, no consent. The browser keeps its log in memory; nothing extra + is sent or stored. + * DEBUG — consented. The server logs this user's requests in detail and stores every line of + them, and the browser streams its own log to `POST /api/diagnostics/events`. + * TRACE — consented. As DEBUG, plus what the user typed into a search. + +A raised level always lapses after `ELEVATION_HOURS`: the expiry is computed HERE at consent time, +never taken from the client, and an expired level reads as INFO without anything having to clear it. +The shared demo account cannot raise its level — its log would mix every visitor's session. + +Core layer: imports `models` and `sysconfig`. +""" + +from datetime import datetime, timedelta, timezone +from typing import Literal, get_args + +from sqlalchemy.orm import Session + +from app import sysconfig +from app.models import User + +DiagnosticsLevel = Literal["INFO", "DEBUG", "TRACE"] +LEVELS: tuple[str, ...] = get_args(DiagnosticsLevel) +BASE: DiagnosticsLevel = "INFO" +ELEVATION_HOURS = 24 + + +def effective_level(user: User, now: datetime | None = None) -> DiagnosticsLevel: + """The level in force for `user` right now: the consented one until it expires, else BASE.""" + level, until = user.diagnostics_level, user.diagnostics_until + if level not in LEVELS or level == BASE or until is None: + return BASE + if until <= (now or datetime.now(timezone.utc)): + return BASE + return level # type: ignore[return-value] — narrowed by the LEVELS check above + + +def state(db: Session, user: User) -> dict: + """The `/api/me` view of it: the level in force, when a raised one lapses, and how long stored + log lines are kept — the consent text states that number, so it must be the instance's own.""" + level = effective_level(user) + return { + "level": level, + "until": user.diagnostics_until.isoformat() if level != BASE else None, + "retention_days": sysconfig.get_int(db, "log_retention_days"), + } + + +def set_level(user: User, level: DiagnosticsLevel) -> None: + """Record a consent (or its withdrawal). The caller commits. Raising the level again restarts + the clock — each consent is for the next ELEVATION_HOURS, not an extension of an older one.""" + if level == BASE: + user.diagnostics_level = None + user.diagnostics_until = None + return + user.diagnostics_level = level + user.diagnostics_until = datetime.now(timezone.utc) + timedelta(hours=ELEVATION_HOURS) diff --git a/backend/app/logs.py b/backend/app/logs.py index 3af0d71d..117a6add 100644 --- a/backend/app/logs.py +++ b/backend/app/logs.py @@ -35,6 +35,7 @@ import logging import logging.config import re import sys +import threading import time import uuid from datetime import datetime, timezone @@ -86,11 +87,44 @@ _CONTEXT_VARS = { } -def set_user(user_id: int | None) -> None: - """Attribute the rest of this request's log lines to `user_id`. Called from the auth dependency - — the one place the session is actually resolved into an account — rather than from the request - middleware, which runs OUTSIDE the session middleware and in a different task context.""" +class _RequestScope: + """What the auth dependency learns about a request, for every line logged after it. + + A MUTABLE object behind a contextvar, not plain contextvars, because of how a request actually + runs: FastAPI resolves a sync dependency (`auth.current_user`) in a threadpool on a COPY of the + context, so a `ContextVar.set()` there is gone by the time the handler runs — measured: that is + how the account never reached a handler's own lines. `log_requests` installs one scope per + request; every copied context shares the same object, so what the dependency writes is seen by + the handler and by the request line itself.""" + + __slots__ = ("user_id", "level") + + def __init__(self) -> None: + self.user_id: int | None = None + # The user's consented diagnostics level as a logging number; None at the base level. + self.level: int | None = None + + +_scope: contextvars.ContextVar[_RequestScope | None] = contextvars.ContextVar( + "log_request_scope", default=None +) + + +def set_user(user_id: int | None, level: str = "INFO", until: datetime | None = None) -> None: + """Attribute the rest of this request's log lines to `user_id`, and log them at the user's + consented diagnostics `level` until `until` (E22 S5; "INFO" = no elevation). Called from the + auth dependency — the one place the session is actually resolved into an account — rather than + from the request middleware, which runs OUTSIDE the session middleware.""" _user_id.set(user_id) + scope = _scope.get() + if scope is None: # outside log_requests (a script, a unit test): this context only + scope = _RequestScope() + _scope.set(scope) + elevated = level != "INFO" and until is not None and until > datetime.now(timezone.utc) + scope.user_id = user_id + scope.level = resolve_level(level) if elevated else None + if user_id is not None: + _track_elevation(user_id, scope.level, until) def set_job(job_id: int | None) -> None: @@ -193,7 +227,7 @@ def redact(value: Any, *, key: str = "") -> Any: # attribute and is merged into `attrs` (so `extra={"job_id": 7}` works as well as `event(...)`). _RECORD_STANDARD = frozenset( vars(logging.LogRecord("", 0, "", 0, "", None, None)).keys() - | {"message", "asctime", "taskName", "event", "attrs", PERSIST} + | {"message", "asctime", "taskName", "event", "attrs", PERSIST, "elevated"} ) @@ -207,9 +241,31 @@ class ContextFilter(logging.Filter): value = var.get() if value is not None and not hasattr(record, name): setattr(record, name, value) + scope = _scope.get() + if scope is not None and scope.user_id is not None and not hasattr(record, "user_id"): + record.user_id = scope.user_id return True +class LevelGate(logging.Filter): + """The configured level, enforced at the HANDLER, with one exception: the lines of a request + whose user raised their diagnostics level (E22 S5). + + The root logger's level cannot do this alone: it is one number for the whole process, and the + point is to log ONE user's requests in detail while everyone else's stay at the base level. So + the root is lowered to the lowest level any active elevation needs (`_track_elevation`), and + this gate drops what only an elevation let through unless the line belongs to that elevated + request. It also marks such a line `elevated`, which is what makes the `log_events` sink keep + every line of that request, not just its warnings.""" + + def filter(self, record: logging.LogRecord) -> bool: + scope = _scope.get() + if scope is not None and scope.level is not None: + record.elevated = True + return record.levelno >= min(scope.level, _base_level) + return record.levelno >= _base_level + + def _record_attrs(record: logging.LogRecord) -> dict[str, Any]: extra = {k: v for k, v in vars(record).items() if k not in _RECORD_STANDARD} attrs = dict(getattr(record, "attrs", None) or {}) @@ -341,29 +397,73 @@ def configure_logging(source: str) -> None: "json": {"()": f"{__name__}.JsonFormatter"}, "text": {"()": f"{__name__}.TextFormatter"}, }, - "filters": {"context": {"()": f"{__name__}.ContextFilter"}}, + "filters": { + "context": {"()": f"{__name__}.ContextFilter"}, + "gate": {"()": f"{__name__}.LevelGate"}, + }, "handlers": { "stdout": { "class": "logging.StreamHandler", "stream": sys.stdout, "formatter": formatter, - "filters": ["context"], + "filters": ["context", "gate"], } }, "root": {"level": resolve_level(settings.log_level), "handlers": ["stdout"]}, "loggers": {name: {"level": lvl} for name, lvl in _THIRD_PARTY_LEVELS.items()}, } ) + set_level(settings.log_level) def set_level(name: str) -> None: """Change the running process's level (the `log_level` admin knob). Third-party loggers keep their pinned levels, so turning on DEBUG shows OUR detail, not SQLAlchemy's.""" - logging.getLogger().setLevel(resolve_level(name)) + global _base_level + _base_level = resolve_level(name) + _apply_root_level(force=True) def current_level() -> str: - return logging.getLevelName(logging.getLogger().getEffectiveLevel()) + """The configured level — not the root logger's, which an active elevation may have lowered.""" + return logging.getLevelName(_base_level or logging.getLogger().getEffectiveLevel()) + + +# --- per-user elevation (E22 S5) ----------------------------------------------------------- +# The base level (`LOG_LEVEL`, then the admin knob). NOTSET until configure_logging runs — a unit +# test, a script — so the gate lets everything through there, as it did before the gate existed. +_base_level = logging.NOTSET +# user id → (level number, expiry) for every elevation this process has seen and not yet expired. +_elevations: dict[int, tuple[int, datetime]] = {} +_elevations_lock = threading.Lock() +_root_applied: int | None = None + + +def _track_elevation(user_id: int, level: int | None, until: datetime | None) -> None: + with _elevations_lock: + if level is None or until is None: + _elevations.pop(user_id, None) + else: + _elevations[user_id] = (level, until) + active = bool(_elevations) + if active or _root_applied != _base_level: + _apply_root_level() + + +def _apply_root_level(force: bool = False) -> None: + """Root level = the lowest of the base and every unexpired elevation (expired ones are pruned + here). `setLevel` clears every logger's level cache, so it runs only when the number changes.""" + global _root_applied + if _base_level == logging.NOTSET: + return # not configured: the root keeps whatever the process set up + now = datetime.now(timezone.utc) + with _elevations_lock: + for user_id in [u for u, (_, until) in _elevations.items() if until <= now]: + del _elevations[user_id] + lowest = min([_base_level, *(lvl for lvl, _ in _elevations.values())]) + if force or lowest != _root_applied: + logging.getLogger().setLevel(lowest) + _root_applied = lowest def current_source() -> str: @@ -397,6 +497,8 @@ async def log_requests(request, call_next): incoming = request.headers.get("x-request-id", "") rid = incoming if _REQUEST_ID_RE.match(incoming) else uuid.uuid4().hex[:16] token = _request_id.set(rid) + scope = _RequestScope() + scope_token = _scope.set(scope) request.state.request_id = rid started = time.perf_counter() try: @@ -417,6 +519,7 @@ async def log_requests(request, call_next): **_request_owner(request, logging.ERROR), }, ) + _scope.reset(scope_token) _request_id.reset(token) raise duration_ms = round((time.perf_counter() - started) * 1000, 1) @@ -428,22 +531,23 @@ async def log_requests(request, call_next): level = logging.WARNING else: level = logging.DEBUG if quiet else logging.INFO + attrs: dict[str, Any] = { + "method": request.method, + "path": _route_template(request), + "status": status, + "duration_ms": duration_ms, + } + # Teljes (TRACE, the user's or the whole process's): the query string too — redacted, and in + # attrs only, never in the message. + if request.url.query and _traced(scope): + attrs["query"] = redact_text(request.url.query) _request_log.log( level, "%s %s %s", request.method, _route_template(request), status, - extra={ - **event( - "http.request", - method=request.method, - path=_route_template(request), - status=status, - duration_ms=duration_ms, - ), - **_request_owner(request, level), - }, + extra={**event("http.request", **attrs), **_request_owner(request, level)}, ) response.headers["X-Request-Id"] = rid # The template, so the browser's copy of this line groups the same way (frontend lib/http.ts). @@ -453,10 +557,18 @@ async def log_requests(request, call_next): matched = _matched_route(request) if matched: response.headers["X-Route"] = matched + _scope.reset(scope_token) _request_id.reset(token) return response +def _traced(scope: _RequestScope) -> bool: + """Whether this request is logged at TRACE — its user's consent, or the process's base level.""" + if scope.level is not None and scope.level <= TRACE: + return True + return _base_level != logging.NOTSET and _base_level <= TRACE + + # Anonymous request lines kept per client per minute. Signed-in traffic is not capped: it is a known # account and exactly what an admin needs to see. Anonymous traffic is where the volume can come from # nobody in particular — a scanner walking `/wp-login.php`, a bot on a share link — and each of its diff --git a/backend/app/logsink.py b/backend/app/logsink.py index 4b2d22f7..fb6d2e38 100644 --- a/backend/app/logsink.py +++ b/backend/app/logsink.py @@ -6,6 +6,8 @@ for `log_retention_days`: * every WARNING and above, * the `http.request` line of every request at INFO or above (not the DEBUG-level health checks and static files), + * every line of a request whose user raised their diagnostics level (E22 S5 — `logs.LevelGate` + marks them), which is the detail they consented to have kept, * nothing a caller marked `extra={logs.PERSIST: False}` — how the request log caps anonymous traffic per client. @@ -71,7 +73,7 @@ def should_store(record: logging.LogRecord) -> bool: """Whether this record belongs in `log_events` (see the module docstring).""" if getattr(record, logs.PERSIST, True) is False: return False - if record.levelno >= logging.WARNING: + if record.levelno >= logging.WARNING or getattr(record, "elevated", False): return True return getattr(record, "event", None) == "http.request" and record.levelno >= logging.INFO @@ -255,6 +257,9 @@ def start() -> None: if _sink is not None or not settings.log_db_sink: return _sink = LogSink() + # The same level gate as stdout: the root may be lowered for one user's elevated requests, and + # everyone else's detail must not reach the table through that gap either. + _sink.addFilter(logs.LevelGate()) logging.getLogger().addHandler(_sink) _sink.start() # A short-lived process (the download child) exits without a lifespan: flush on the way out. diff --git a/backend/app/main.py b/backend/app/main.py index dbebb992..a4c1f44a 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -36,6 +36,7 @@ from app.routes import ( auth as auth_routes, channels, config as config_routes, + diagnostics as diagnostics_routes, discover as discover_routes, downloads, feed, @@ -270,6 +271,7 @@ app.include_router(feed.router) app.include_router(discover_routes.router) app.include_router(search_routes.router) app.include_router(me.router) +app.include_router(diagnostics_routes.router) app.include_router(notifications.router) app.include_router(messages.router) app.include_router(channels.router) diff --git a/backend/app/models.py b/backend/app/models.py index f414f92a..7878ffdb 100644 --- a/backend/app/models.py +++ b/backend/app/models.py @@ -107,6 +107,12 @@ class User(Base, TimestampMixin, CanonicalEmailMixin): # routes/auth._establish_session. NULL = not since the column existed (0085; no backfill is # possible). The shared demo account is never stamped — its "last login" would mean nobody. last_login_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True)) + # The diagnostics level this user consented to (E22 S5) and when it lapses back to the base + # level. Both NULL = base. Written only by `PUT /api/me/diagnostics`, which computes the expiry + # itself; read through `app.diagnostics.effective_level`, never directly (an expired level is + # not cleared eagerly — it simply stops counting). + diagnostics_level: Mapped[str | None] = mapped_column(String(8)) + diagnostics_until: Mapped[datetime | None] = mapped_column(DateTime(timezone=True)) display_name: Mapped[str | None] = mapped_column(String(255)) avatar_url: Mapped[str | None] = mapped_column(String(1024)) role: Mapped[str] = mapped_column(String(16), default="user", server_default="user") diff --git a/backend/app/routes/diagnostics.py b/backend/app/routes/diagnostics.py new file mode 100644 index 00000000..277f8392 --- /dev/null +++ b/backend/app/routes/diagnostics.py @@ -0,0 +1,135 @@ +"""The browser's log, sent while its user has a raised diagnostics level (E22 S5). + +The client keeps its log in memory (frontend `lib/log.ts`). Only after the user consented to Részletes +or Teljes in Settings → Diagnosztika does it stream that log here, in batches, and each batch lands in +`log_events` beside the server's own rows: `source="web"`, the account from the SESSION (never from +the body), and the request id each event carries, which is what joins a browser line to the server +line of the same request. + +Nothing from the body is trusted as-is: + * the whole body is capped before it is parsed, and so are the number of events and each event's + attributes; + * everything is redacted AGAIN with the server's own rules — the client redacts at capture, but a + modified client would not; + * an event below the consented level is dropped (a Részletes consent does not store what only + Teljes may carry), and so is the whole batch once the level has lapsed; + * the timestamp is clamped to the consent window, so a row cannot dodge the retention job by + claiming to come from the future. +""" + +import json +from datetime import datetime, timedelta, timezone +from typing import Any, Literal + +from fastapi import APIRouter, Depends, HTTPException, Request +from pydantic import BaseModel, Field, ValidationError +from sqlalchemy import insert +from sqlalchemy.orm import Session + +from app import diagnostics, logs, logsink +from app.auth import current_user +from app.db import get_db +from app.models import LogEvent, User +from app.ratelimit import RateLimiter + +router = APIRouter(prefix="/api/diagnostics", tags=["diagnostics"]) + +BODY_MAX_BYTES = 512 * 1024 +EVENTS_MAX = 200 +ATTRS_MAX_BYTES = 16 * 1024 +# The client flushes every few seconds and when its buffer fills; this is room for a burst, not a +# pace anything legitimate keeps up for a minute. +_batches = RateLimiter(max_events=30, window_seconds=60) + +ClientLevel = Literal["TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] + + +class ClientEvent(BaseModel): + ts: datetime + level: ClientLevel + event: str = Field(max_length=64, pattern=r"^[a-z][a-z0-9_]*(\.[a-z0-9_]+)*$") + msg: str = Field(max_length=8_000) + attrs: dict[str, Any] | None = None + request_id: str | None = Field(default=None, pattern=r"^[A-Za-z0-9._-]{8,64}$") + tab_id: str | None = Field(default=None, pattern=r"^[A-Za-z0-9_-]{1,32}$") + version: str | None = Field(default=None, max_length=64) + + +class ClientEventsIn(BaseModel): + events: list[ClientEvent] = Field(max_length=EVENTS_MAX) + + +async def _capped_body(request: Request) -> bytes: + """The request body, refused the moment it passes BODY_MAX_BYTES while still arriving. Counted, + not taken from Content-Length: a declared length can be absent (chunked) or wrong, and counting + stops reading at the same point a declared-length check would have.""" + body = bytearray() + async for chunk in request.stream(): + body += chunk + if len(body) > BODY_MAX_BYTES: + raise HTTPException(status_code=413, detail={"code": "too_large"}) + return bytes(body) + + +async def _parsed_events(request: Request) -> ClientEventsIn: + """The body as the model — parsed only after the size cap, which is why this is a dependency and + not a plain body parameter (FastAPI reads a declared body in full before anything else runs).""" + raw = await _capped_body(request) + try: + return ClientEventsIn.model_validate_json(raw) + except ValidationError as exc: + raise HTTPException(status_code=422, detail=json.loads(exc.json())) from exc + + +def _row(item: ClientEvent, user: User, now: datetime, window_start: datetime) -> dict[str, Any]: + attrs = logs.redact(item.attrs) if item.attrs else None + if attrs is not None: + size = len(json.dumps(attrs, ensure_ascii=False, default=str).encode()) + if size > ATTRS_MAX_BYTES: + attrs = {"attrs_dropped_bytes": size} + if item.tab_id: + attrs = {**(attrs or {}), "tab_id": item.tab_id} + ts = item.ts if item.ts.tzinfo else item.ts.replace(tzinfo=timezone.utc) + return logsink.to_row( + { + "ts": min(max(ts, window_start), now), + "level": item.level, + "sev": logs.SEVERITY[item.level], + "source": "web", + "logger": "web", + "event": item.event, + "msg": logs.redact_text(item.msg), + "attrs": attrs, + "request_id": item.request_id, + "user_id": user.id, + "version": item.version, + } + ) + + +@router.post("/events") +def ingest_events( + # The account first: dependencies resolve in order, so an anonymous caller is refused before a + # byte of its body is read. + user: User = Depends(current_user), + body: ClientEventsIn = Depends(_parsed_events), + db: Session = Depends(get_db), +) -> dict: + level = diagnostics.effective_level(user) + if level == diagnostics.BASE: + # Lapsed or withdrawn: the client stops streaming when it sees this. + raise HTTPException(status_code=409, detail={"code": "diagnostics_off"}) + if not _batches.allow(str(user.id)): + raise HTTPException(status_code=429, detail={"code": "rate_limited"}) + now = datetime.now(timezone.utc) + window_start = now - timedelta(hours=diagnostics.ELEVATION_HOURS) + floor = logs.SEVERITY[level] + rows = [ + _row(item, user, now, window_start) + for item in body.events + if logs.SEVERITY[item.level] >= floor + ] + if rows: + db.execute(insert(LogEvent), rows) + db.commit() + return {"ok": True, "stored": len(rows)} diff --git a/backend/app/routes/me.py b/backend/app/routes/me.py index 6f50f2dd..eb586a22 100644 --- a/backend/app/routes/me.py +++ b/backend/app/routes/me.py @@ -1,5 +1,7 @@ +from typing import Any + from fastapi import APIRouter, BackgroundTasks, Depends, HTTPException, Request -from pydantic import BaseModel +from pydantic import BaseModel, RootModel from sqlalchemy import func, select from sqlalchemy.orm import Session @@ -15,7 +17,9 @@ from app.auth import ( optional_current_user, purge_user, ) +from app import diagnostics from app import email as email_mod +from app import logs from app import sysconfig from app.db import get_db from app.models import Invite, User @@ -147,6 +151,9 @@ def get_me( "pending_activations": pending_activations, "email_configured": email_configured, "preferences": user.preferences or {}, + # The consented diagnostics level in force and when it lapses (E22 S5). The client applies + # it to its own log and streams that log while it is raised. + "diagnostics": diagnostics.state(db, user), } @@ -188,16 +195,45 @@ def delete_my_account( return {"deleted": True} +class PreferencesIn(RootModel[dict[str, Any]]): + """Free-form UI preferences — a JSON object of any keys (theme, filters, …), merged into the + stored ones. A model rather than a bare `dict` parameter so a non-object body is a 422 at the + boundary like every other request body.""" + + @router.put("/preferences") def update_preferences( - preferences: dict, + preferences: PreferencesIn, user: User = Depends(current_user), db: Session = Depends(get_db), ) -> dict: # Merge so partial updates don't wipe other keys. merged = dict(user.preferences or {}) - merged.update(preferences) + merged.update(preferences.root) user.preferences = merged db.add(user) db.commit() return {"preferences": merged} + + +class DiagnosticsIn(BaseModel): + level: diagnostics.DiagnosticsLevel + + +@router.put("/diagnostics") +def update_diagnostics( + body: DiagnosticsIn, + user: User = Depends(current_user), + db: Session = Depends(get_db), +) -> dict: + """Raise the diagnostics level (the user consented in Settings → Diagnosztika) or return to the + base. The expiry is the server's: a raised level always lapses after + `diagnostics.ELEVATION_HOURS`, whatever the client asks. The shared demo account cannot raise + it — its log would interleave every visitor's session under one account.""" + if user.is_demo and body.level != diagnostics.BASE: + raise HTTPException(status_code=403, detail={"code": "demo", "reason": "diagnostics"}) + diagnostics.set_level(user, body.level) + db.commit() + # The rest of THIS request, and the process's elevation registry, follow the new level now. + logs.set_user(user.id, diagnostics.effective_level(user), user.diagnostics_until) + return {"ok": True, "diagnostics": diagnostics.state(db, user)} diff --git a/backend/tests/test_demo_refusal_detail.py b/backend/tests/test_demo_refusal_detail.py index f629f9cf..1a933508 100644 --- a/backend/tests/test_demo_refusal_detail.py +++ b/backend/tests/test_demo_refusal_detail.py @@ -7,14 +7,14 @@ of the caller's already-translated fallback, so from that commit on the demo use this gate is UI-gated on `is_demo` either — the comfort shelf is not, so the pin button is live. A structured `{code: "demo"}` is what `localizeDetail` can turn into `errors.demo` in both locales. -Pinned at all FOUR sites: the shared dependency, the two auth routes that hand-roll the same check, -and the account-delete route in `routes/me.py` — which round 6 missed while its docstring claimed +Pinned at every site: the shared dependency, the two auth routes that hand-roll the same check, +the account-delete route in `routes/me.py` — which round 6 missed while its docstring claimed all the sites were covered, so the next reader had no reason to look (round 7). An asymmetric fix is the smell this repo bans, and a docstring asserting symmetry it does not have is worse than none. The list is derived from the source, not typed out: `test_every_is_demo_refusal_is_on_the_list` below fails when a fifth `is_demo` 403 appears anywhere in `app/`, so this file cannot fall behind -the code the way round 6's did. Needs the DB. +the code the way round 6's did. (E22 S5 added the fifth: raising the diagnostics level.) Needs the DB. """ import re @@ -33,6 +33,8 @@ def test_every_demo_refusal_carries_the_same_structured_reason(db, make_user, as ("post", "/auth/logout-others", None), ("post", "/auth/set-password", {"password": "a long enough password"}), ("delete", "/api/me/account", None), + # E22 S5: the shared account's log would interleave every visitor's session. + ("put", "/api/me/diagnostics", {"level": "DEBUG"}), ]: r = getattr(client, method)(url, **({"json": body} if body is not None else {})) assert r.status_code == 403, (url, r.text) @@ -55,9 +57,9 @@ def test_every_is_demo_refusal_is_on_the_list(): for path in sorted(app_dir.rglob("*.py")): lines = path.read_text(encoding="utf-8").splitlines() for i, line in enumerate(lines): - # `if user.is_demo:` / `if u.is_demo:` — the hand-rolled gate, not the ORM filters - # (`User.is_demo.is_(False)`) and not the column definition. - if not re.search(r"^\s*if\s+\w+\.is_demo\s*:", line): + # `if user.is_demo:` / `if u.is_demo and …:` — the hand-rolled gate, not the ORM + # filters (`User.is_demo.is_(False)`) and not the column definition. + if not re.search(r"^\s*if\s+\w+\.is_demo\b[^:]*:", line): continue block = "\n".join(lines[i : i + 6]) if "403" not in block: @@ -67,9 +69,9 @@ def test_every_is_demo_refusal_is_on_the_list(): f"{path.relative_to(app_dir)}:{i + 1} refuses the demo account with an " f"unstructured detail — the frontend cannot localize it:\n{block}" ) - # auth.py's shared gate + routes/auth.py's two + routes/me.py's delete. A new one is welcome, - # but it has to be added to the loop above in the same commit. - assert len(sites) == 4, sites + # auth.py's shared gate + routes/auth.py's two + routes/me.py's delete and diagnostics level. A + # new one is welcome, but it has to be added to the loop above in the same commit. + assert len(sites) == 5, sites def test_a_real_account_is_not_refused_by_the_gate(db, make_user, as_user): diff --git a/backend/tests/test_diagnostics.py b/backend/tests/test_diagnostics.py new file mode 100644 index 00000000..78f9bd95 --- /dev/null +++ b/backend/tests/test_diagnostics.py @@ -0,0 +1,340 @@ +"""E22 S5 — a user's consented diagnostics level, and the browser log it lets in. + +Three parts: + * the level itself: the server computes its expiry, a lapsed one reads as the base, the demo + account cannot raise it (DB lane, through the real routes); + * `POST /api/diagnostics/events`: refused at the base level, and nothing in a batch is trusted — + the account comes from the session, everything is redacted again, events under the consented + level are dropped, sizes and pace are capped (DB lane); + * the server side of the elevation: ONE user's requests are logged in detail while everyone + else's stay at the base level, and the account reaches a handler's own lines at all (pure, an + in-process app). +""" + +import json +import logging +from datetime import datetime, timedelta, timezone + +import pytest +from fastapi import Depends, FastAPI +from fastapi.testclient import TestClient +from sqlalchemy import select + +from app import diagnostics, logs, logsink +from app.models import LogEvent, User +from app.routes import diagnostics as diagnostics_routes + +_PW = "correct horse battery" + + +# --- the level ------------------------------------------------------------------------------ + + +def test_a_raised_level_counts_until_it_lapses_and_not_a_moment_longer(): + now = datetime.now(timezone.utc) + assert diagnostics.effective_level(User()) == "INFO" + raised = User(diagnostics_level="TRACE", diagnostics_until=now + timedelta(minutes=1)) + assert diagnostics.effective_level(raised, now) == "TRACE" + assert diagnostics.effective_level(raised, now + timedelta(minutes=2)) == "INFO" + # A level without an expiry is not a level that never ends — it is no level at all. + assert diagnostics.effective_level(User(diagnostics_level="DEBUG")) == "INFO" + + +def _signed_in(client, make_user, **kw): + """A real sign-in: `/api/me` resolves through `optional_current_user`, which the `as_user` + override does not cover (see test_me_email_flag).""" + user = make_user(email="diag@example.com", password=_PW, **kw) + r = client.post("/auth/password-login", json={"email": "diag@example.com", "password": _PW}) + assert r.status_code == 200, r.text + return user + + +def test_raising_the_level_sets_the_servers_expiry_whatever_the_client_sends(db, client, make_user): + user = _signed_in(client, make_user) + r = client.put("/api/me/diagnostics", json={"level": "DEBUG", "until": "2099-01-01T00:00:00Z"}) + assert r.status_code == 200, r.text + db.refresh(user) + expected = datetime.now(timezone.utc) + timedelta(hours=diagnostics.ELEVATION_HOURS) + assert abs((user.diagnostics_until - expected).total_seconds()) < 60 + assert r.json()["diagnostics"]["level"] == "DEBUG" + assert client.get("/api/me").json()["diagnostics"]["level"] == "DEBUG" + + assert client.put("/api/me/diagnostics", json={"level": "INFO"}).status_code == 200 + db.refresh(user) + assert (user.diagnostics_level, user.diagnostics_until) == (None, None) + assert client.get("/api/me").json()["diagnostics"] == { + "level": "INFO", + "until": None, + "retention_days": 7, + } + + +def test_a_lapsed_level_reads_as_the_base_in_me(db, client, make_user): + _signed_in( + client, + make_user, + diagnostics_level="TRACE", + diagnostics_until=datetime.now(timezone.utc) - timedelta(minutes=1), + ) + assert client.get("/api/me").json()["diagnostics"] == { + "level": "INFO", + "until": None, + "retention_days": 7, + } + + +def test_only_the_three_levels_can_be_chosen(db, make_user, as_user): + client = as_user(make_user()) + for bogus in ("WARNING", "debug", "EVERYTHING"): + assert client.put("/api/me/diagnostics", json={"level": bogus}).status_code == 422 + + +def test_the_demo_account_can_return_to_the_base_but_never_raise_it(db, make_user, as_user): + client = as_user(make_user(is_demo=True)) + r = client.put("/api/me/diagnostics", json={"level": "TRACE"}) + assert r.status_code == 403 and r.json()["detail"]["code"] == "demo" + assert client.put("/api/me/diagnostics", json={"level": "INFO"}).status_code == 200 + + +def test_preferences_must_be_a_json_object(db, make_user, as_user): + client = as_user(make_user()) + assert client.put("/api/me/preferences", json=["not", "an", "object"]).status_code == 422 + r = client.put("/api/me/preferences", json={"theme": "dark"}) + assert r.status_code == 200 and r.json()["preferences"]["theme"] == "dark" + + +# --- the browser's batches ------------------------------------------------------------------ + + +def _event(**over) -> dict: + return { + "ts": datetime.now(timezone.utc).isoformat(), + "level": "INFO", + "event": "nav.view", + "msg": "view", + "tab_id": "a1b2c3", + "version": "0.88.0", + **over, + } + + +@pytest.fixture +def elevated(db, make_user, as_user): + """A signed-in client whose user consented to `level` a minute ago, and a reader for its rows.""" + diagnostics_routes._batches.reset() + + def _make(level: str = "DEBUG"): + user = make_user( + diagnostics_level=level, + diagnostics_until=datetime.now(timezone.utc) + timedelta(hours=23), + ) + + def rows() -> list[LogEvent]: + db.expire_all() + return list(db.execute(select(LogEvent).order_by(LogEvent.id)).scalars()) + + return user, as_user(user), rows + + yield _make + diagnostics_routes._batches.reset() + + +def test_nothing_is_accepted_at_the_base_level(db, make_user, as_user): + client = as_user(make_user()) + r = client.post("/api/diagnostics/events", json={"events": [_event()]}) + assert r.status_code == 409 and r.json()["detail"]["code"] == "diagnostics_off" + assert not db.execute(select(LogEvent)).first() + + +def test_an_anonymous_caller_is_refused(client): + assert client.post("/api/diagnostics/events", json={"events": [_event()]}).status_code == 401 + + +def test_a_batch_is_stored_as_the_sessions_web_events_and_redacted_again(elevated): + user, client, rows = elevated("DEBUG") + r = client.post( + "/api/diagnostics/events", + json={ + "events": [ + _event( + level="WARNING", + event="ui.notify", + msg="sent to someone@example.com", + attrs={"password": "hunter2", "url": "/?token=abc123", "user_id": 999}, + request_id="0123456789abcdef", + ), + _event(level="DEBUG", event="ui.click", attrs={"control": "feed.refresh"}), + ], + "user_id": 999, # ignored: the account is the session's + }, + ) + assert r.json() == {"ok": True, "stored": 2} + warning, click = rows() + assert (warning.source, warning.logger, warning.user_id) == ("web", "web", user.id) + assert warning.msg == "sent to [email]" + assert warning.attrs["password"] == logs.REDACTED + assert "abc123" not in json.dumps(warning.attrs) + assert warning.attrs["tab_id"] == "a1b2c3" + assert warning.request_id == "0123456789abcdef" + assert (warning.sev, click.level, click.version) == (13, "DEBUG", "0.88.0") + + +def test_an_event_under_the_consented_level_is_dropped(elevated): + _user, client, rows = elevated("DEBUG") + r = client.post( + "/api/diagnostics/events", + json={"events": [_event(level="TRACE", msg="typed: lofi"), _event(level="DEBUG")]}, + ) + assert r.json()["stored"] == 1 + assert [row.level for row in rows()] == ["DEBUG"] + + +def test_a_timestamp_outside_the_consent_window_is_clamped(elevated): + _user, client, rows = elevated("DEBUG") + now = datetime.now(timezone.utc) + future = (now + timedelta(days=365)).isoformat() + past = (now - timedelta(days=30)).isoformat() + client.post("/api/diagnostics/events", json={"events": [_event(ts=future), _event(ts=past)]}) + late, early = rows() + assert late.ts <= datetime.now(timezone.utc) + assert early.ts >= now - timedelta(hours=diagnostics.ELEVATION_HOURS, minutes=1) + + +def test_sizes_are_capped(elevated): + _user, client, rows = elevated("DEBUG") + too_many = [_event() for _ in range(diagnostics_routes.EVENTS_MAX + 1)] + assert client.post("/api/diagnostics/events", json={"events": too_many}).status_code == 422 + + huge = "x" * (diagnostics_routes.BODY_MAX_BYTES + 1) + r = client.post( + "/api/diagnostics/events", + content=json.dumps({"events": [_event(attrs={"blob": huge})]}), + headers={"content-type": "application/json"}, + ) + assert r.status_code == 413 + + big_attrs = {"blob": "y" * (diagnostics_routes.ATTRS_MAX_BYTES + 10)} + assert ( + client.post("/api/diagnostics/events", json={"events": [_event(attrs=big_attrs)]}).json()[ + "stored" + ] + == 1 + ) + (row,) = rows() + assert "blob" not in row.attrs and row.attrs["attrs_dropped_bytes"] > 0 + + bad_code = client.post("/api/diagnostics/events", json={"events": [_event(event="Nav View")]}) + assert bad_code.status_code == 422 + + +def test_the_pace_is_capped_per_user(elevated): + _user, client, _rows = elevated("DEBUG") + codes = [ + client.post("/api/diagnostics/events", json={"events": []}).status_code for _ in range(31) + ] + assert codes[:30] == [200] * 30 and codes[30] == 429 + + +# --- the server side of an elevation --------------------------------------------------------- + + +class _Capture(logging.Handler): + """The stdout handler's filters (context + gate), capturing records.""" + + def __init__(self): + super().__init__(level=logging.NOTSET) + self.records: list[logging.LogRecord] = [] + self.addFilter(logs.ContextFilter()) + self.addFilter(logs.LevelGate()) + + def emit(self, record): + self.records.append(record) + + +@pytest.fixture +def gated(): + """A process configured at INFO with a gated handler on the ROOT (where the real one sits), and + every piece of module state the elevation touches restored afterwards.""" + root = logging.getLogger() + saved = (logs._base_level, dict(logs._elevations), logs._root_applied, root.level) + handler = _Capture() + root.addHandler(handler) + logs._elevations.clear() + logs.set_level("INFO") + try: + yield handler + finally: + root.removeHandler(handler) + logs._base_level, logs._root_applied = saved[0], saved[2] + logs._elevations.clear() + logs._elevations.update(saved[1]) + root.setLevel(saved[3]) + + +def _app() -> TestClient: + """What a real request does: the request middleware, then a SYNC auth dependency that resolves + the account (run by FastAPI in a threadpool, on a copy of the context), then a handler.""" + app = FastAPI() + app.middleware("http")(logs.log_requests) + handler_log = logging.getLogger("siftlode.difftest") + + def account(user_id: int, level: str = "INFO"): + until = datetime.now(timezone.utc) + timedelta(hours=1) + logs.set_user(user_id, level, until) + + @app.get("/api/thing/{user_id}") + def _thing(user_id: int, _=Depends(account)): + handler_log.debug("detail only an elevated request keeps") + handler_log.info("an ordinary line") + return {} + + return TestClient(app) + + +def test_the_account_reaches_the_handlers_own_lines(gated): + _app().get("/api/thing/41") + line = next(r for r in gated.records if r.getMessage() == "an ordinary line") + assert getattr(line, "user_id", None) == 41 + + +def test_one_users_elevation_logs_their_requests_in_detail_and_nobody_elses(gated): + client = _app() + client.get("/api/thing/7", params={"level": "DEBUG"}) + client.get("/api/thing/8") + detail = [r for r in gated.records if r.getMessage().startswith("detail only")] + assert [r.user_id for r in detail] == [7] + assert getattr(detail[0], "elevated", False) is True + # Every line of the elevated request is marked for storage — the sink keeps it at any level. + ordinary = [r for r in gated.records if r.getMessage() == "an ordinary line"] + assert [logsink.should_store(r) for r in ordinary] == [True, False] + # The process's configured level is still what it reports, however low the root went. + assert logs.current_level() == "INFO" and logging.getLogger().level == logging.DEBUG + + +def test_the_root_level_returns_to_the_base_when_the_elevation_ends(gated): + client = _app() + client.get("/api/thing/7", params={"level": "TRACE"}) + assert logging.getLogger().level == logs.TRACE + client.get("/api/thing/7") # the same user, back at the base + assert logging.getLogger().level == logging.INFO + logs._track_elevation(9, logging.DEBUG, datetime.now(timezone.utc) - timedelta(seconds=1)) + assert logging.getLogger().level == logging.INFO # an already-expired one is pruned at once + + +def test_the_query_string_is_logged_only_for_a_traced_request_and_redacted(gated): + client = _app() + client.get("/api/thing/7", params={"level": "DEBUG", "q": "lofi"}) + client.get("/api/thing/7", params={"level": "TRACE", "q": "lofi", "token": "SECRET"}) + lines = [r for r in gated.records if getattr(r, "event", None) == "http.request"] + assert "query" not in lines[0].attrs + assert "q=lofi" in lines[1].attrs["query"] and "SECRET" not in lines[1].attrs["query"] + + +def test_a_real_sign_in_carries_the_consented_level_into_the_process(gated, client, db, make_user): + user = _signed_in(client, make_user) + assert client.put("/api/me/diagnostics", json={"level": "DEBUG"}).status_code == 200 + logs._elevations.clear() # only a request resolving the account through auth may put it back + client.get("/api/me") + assert logs._elevations[user.id][0] == logging.DEBUG + assert client.put("/api/me/diagnostics", json={"level": "INFO"}).status_code == 200 + assert user.id not in logs._elevations diff --git a/frontend/src/App.tsx b/frontend/src/App.tsx index 70242390..73212970 100644 --- a/frontend/src/App.tsx +++ b/frontend/src/App.tsx @@ -48,6 +48,7 @@ import { focusAccessRequestsTab } from "./lib/adminUsersTab"; // pulls its whole ~900-line changelog into the eager App chunk and defeats the lazy ReleaseNotes // split. FRONTEND_VERSION equals RELEASE_NOTES[0].version by release convention (both bump together). import { FRONTEND_VERSION } from "./lib/version"; +import { applyDiagnostics } from "./lib/diagnostics"; // The page modules (and their side rails) are code-split per route via the module registry // (components/moduleRegistry). App keeps only the persistent-shell chunks + the channel page and the @@ -151,6 +152,14 @@ export default function App() { meQuery.data ? [...moduleOrder(meQuery.data), "settings"] : [], ); + // The account's consented diagnostics level (E22 S5), applied to this tab's log: raised, the log is + // kept in more detail and streamed to the server until the level lapses. A lapse (its own timer, or + // the server saying it is off) refetches `me`, so Settings shows the base level again. + const diagnostics = meQuery.data?.diagnostics; + useEffect(() => { + applyDiagnostics(diagnostics, () => void queryClient.invalidateQueries({ queryKey: qk.me() })); + }, [diagnostics?.level, diagnostics?.until]); // eslint-disable-line react-hooks/exhaustive-deps + // Fetch the code of every module this account can open — and the channel page — once the first page // is on screen, so a module's first visit renders at once instead of flashing the chunk fallback. // Idle-scheduled so it never competes with the first page's own requests (Safari has no diff --git a/frontend/src/components/DiagnosticsSettings.dom.test.tsx b/frontend/src/components/DiagnosticsSettings.dom.test.tsx new file mode 100644 index 00000000..48e5b165 --- /dev/null +++ b/frontend/src/components/DiagnosticsSettings.dom.test.tsx @@ -0,0 +1,130 @@ +// @vitest-environment jsdom +// +// E22 S5: Settings → Diagnosztika. Raising the level is a consent, so choosing Részletes or Teljes +// must change NOTHING until the consent box's own button is pressed; going back to Alap needs no +// consent. i18n is a key-passthrough (with the count, so the retention days are visible); the level +// endpoint is stubbed, and `me` lives in a real query cache so a saved level re-renders like in the app. +import { afterEach, describe, expect, it, vi } from "vitest"; +import { cleanup, fireEvent, render, screen, waitFor, within } from "@testing-library/react"; +import { QueryClient, QueryClientProvider } from "@tanstack/react-query"; + +import type { DiagnosticsLevel, DiagnosticsState, Me } from "../lib/api"; +import { qk } from "../lib/queryKeys"; + +vi.mock("react-i18next", async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + useTranslation: () => ({ + t: (key: string, opts?: { count?: number }) => + opts?.count != null ? `${key}:${opts.count}` : key, + i18n: { language: "en" }, + }), + }; +}); + +const setLevel = vi.fn( + (level: DiagnosticsLevel): Promise<{ ok: true; diagnostics: DiagnosticsState }> => + Promise.resolve({ + ok: true, + diagnostics: { + level, + until: level === "INFO" ? null : new Date(Date.now() + 86_400_000).toISOString(), + retention_days: 7, + }, + }), +); +vi.mock("../lib/api", async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + api: { ...actual.api, setDiagnosticsLevel: (l: DiagnosticsLevel) => setLevel(l) }, + }; +}); + +import DiagnosticsSettings from "./DiagnosticsSettings"; + +afterEach(() => { + cleanup(); + vi.clearAllMocks(); +}); + +function mount(me: Partial) { + const qc = new QueryClient(); + qc.setQueryData(qk.me(), { + id: 1, + is_demo: false, + preferences: {}, + diagnostics: { level: "INFO", until: null, retention_days: 7 }, + ...me, + }); + render( + + + , + ); +} + +const levelButton = (name: string) => + within(screen.getByRole("group", { name: "settings.diagnostics.level" })).getByRole("button", { + name, + }); + +describe("DiagnosticsSettings", () => { + it("choosing a detailed level asks first and changes nothing until confirmed", async () => { + mount({}); + fireEvent.click(levelButton("settings.diagnostics.levels.DEBUG")); + const consent = screen.getByTestId("diagnostics-consent"); + expect(consent.textContent).toContain("settings.diagnostics.consent.what.DEBUG"); + expect(consent.textContent).toContain("settings.diagnostics.consent.server:7"); + expect(setLevel).not.toHaveBeenCalled(); + + fireEvent.click( + within(consent).getByRole("button", { name: "settings.diagnostics.consent.cancel" }), + ); + expect(screen.queryByTestId("diagnostics-consent")).toBeNull(); + expect(levelButton("settings.diagnostics.levels.INFO").getAttribute("aria-pressed")).toBe( + "true", + ); + expect(setLevel).not.toHaveBeenCalled(); + }); + + it("the consent button raises the level, and the status line offers the way back", async () => { + mount({}); + fireEvent.click(levelButton("settings.diagnostics.levels.TRACE")); + fireEvent.click(screen.getByTestId("diagnostics-consent-confirm")); + await waitFor(() => expect(screen.getByTestId("diagnostics-status")).toBeTruthy()); + expect(setLevel).toHaveBeenCalledWith("TRACE"); + expect(screen.queryByTestId("diagnostics-consent")).toBeNull(); + expect(levelButton("settings.diagnostics.levels.TRACE").getAttribute("aria-pressed")).toBe( + "true", + ); + + fireEvent.click(screen.getByRole("button", { name: "settings.diagnostics.revert" })); + await waitFor(() => expect(screen.queryByTestId("diagnostics-status")).toBeNull()); + expect(setLevel).toHaveBeenLastCalledWith("INFO"); + }); + + it("going back to the base level needs no consent", async () => { + const until = new Date(Date.now() + 3_600_000).toISOString(); + mount({ diagnostics: { level: "DEBUG", until, retention_days: 7 } }); + fireEvent.click(levelButton("settings.diagnostics.levels.INFO")); + expect(screen.queryByTestId("diagnostics-consent")).toBeNull(); + await waitFor(() => expect(setLevel).toHaveBeenCalledWith("INFO")); + }); + + it("a lapsed level shows as the base level", () => { + const until = new Date(Date.now() - 60_000).toISOString(); + mount({ diagnostics: { level: "TRACE", until, retention_days: 7 } }); + expect(levelButton("settings.diagnostics.levels.INFO").getAttribute("aria-pressed")).toBe( + "true", + ); + expect(screen.queryByTestId("diagnostics-status")).toBeNull(); + }); + + it("the shared demo account gets an explanation instead of the picker", () => { + mount({ is_demo: true }); + expect(screen.queryByRole("group", { name: "settings.diagnostics.level" })).toBeNull(); + expect(screen.getByText("settings.diagnostics.demo")).toBeTruthy(); + }); +}); diff --git a/frontend/src/components/DiagnosticsSettings.tsx b/frontend/src/components/DiagnosticsSettings.tsx new file mode 100644 index 00000000..8b0380fd --- /dev/null +++ b/frontend/src/components/DiagnosticsSettings.tsx @@ -0,0 +1,159 @@ +import { useEffect, useState } from "react"; +import { useMutation, useQueryClient } from "@tanstack/react-query"; +import { useTranslation } from "react-i18next"; + +import { api, type DiagnosticsLevel, type Me } from "../lib/api"; +import { levelInForce } from "../lib/diagnostics"; +import { qk } from "../lib/queryKeys"; +import { useMe } from "../lib/useMe"; +import { Button } from "./ui/Button"; +import InlineNotice from "./ui/InlineNotice"; +import SegmentedToggle from "./ui/SegmentedToggle"; +import { Section, SettingRow } from "./ui/form"; +import MyLogViewer from "./MyLogViewer"; + +const LEVELS: readonly DiagnosticsLevel[] = ["INFO", "DEBUG", "TRACE"]; + +/** Hours and minutes until `until`, refreshed every 30 s — the status line counts down. */ +function useRemaining(until: string | null): { h: number; m: number } | null { + const [now, setNow] = useState(() => Date.now()); + useEffect(() => { + if (!until) return; + const id = window.setInterval(() => setNow(Date.now()), 30_000); + return () => window.clearInterval(id); + }, [until]); + if (!until) return null; + const minutes = Math.max(0, Math.ceil((Date.parse(until) - now) / 60_000)); + return { h: Math.floor(minutes / 60), m: minutes % 60 }; +} + +// Settings → Diagnosztika (E22 S5): the consented diagnostics level and the tab's own log. +// +// There is no separate on/off switch: Alap IS off. Choosing Részletes or Teljes does not change +// anything yet — it opens the consent box under the picker, which says what will be recorded, that +// the server keeps it and for how long, and that it lapses; only its button raises the level. +// Returning to Alap needs no consent and happens at once. +export default function DiagnosticsSettings() { + const { t } = useTranslation(); + const me = useMe(); + const qc = useQueryClient(); + const state = me.diagnostics; + const current = levelInForce(state); + const [pending, setPending] = useState(null); + const remaining = useRemaining(current === "INFO" ? null : (state?.until ?? null)); + + const change = useMutation({ + mutationFn: api.setDiagnosticsLevel, + meta: { failTitle: "settings.diagnostics.failed" }, + onSuccess: (result) => { + qc.setQueryData(qk.me(), (prev) => + prev ? { ...prev, diagnostics: result.diagnostics } : prev, + ); + setPending(null); + }, + }); + + const choose = (level: DiagnosticsLevel) => { + if (level === "INFO") { + setPending(null); + if (current !== "INFO") change.mutate("INFO"); + } else { + setPending(level === current ? null : level); + } + }; + + const levelName = (level: DiagnosticsLevel) => t(`settings.diagnostics.levels.${level}`); + + return ( + <> +
+ {me.is_demo ? ( + {t("settings.diagnostics.demo")} + ) : ( + + ({ value: level, label: levelName(level) }))} + /> + + )} + + {pending && ( +
+

{t(`settings.diagnostics.consent.title.${pending}`)}

+
    +
  • {t(`settings.diagnostics.consent.what.${pending}`)}
    • +
  • + {t("settings.diagnostics.consent.server", { + count: state?.retention_days ?? 7, + })} +
    • +
  • {t("settings.diagnostics.consent.never")}
    • +
  • + {t("settings.diagnostics.consent.lapse")}{" "} + + {t("settings.diagnostics.consent.policy")} + +
    • +
+
+ + +
+
+ )} + + {current !== "INFO" && !pending && remaining && ( +
+ + + + {t("settings.diagnostics.status", { + level: levelName(current), + time: + remaining.h > 0 + ? t("settings.diagnostics.hoursMinutes", remaining) + : t("settings.diagnostics.minutes", remaining), + })} + + + +
+ )} +
+ +
+ +
+ + ); +} diff --git a/frontend/src/components/FeedFiltersProvider.tsx b/frontend/src/components/FeedFiltersProvider.tsx index ef6d3aeb..d481a381 100644 --- a/frontend/src/components/FeedFiltersProvider.tsx +++ b/frontend/src/components/FeedFiltersProvider.tsx @@ -20,6 +20,7 @@ import { import { filterParamUpdates, hasFilterParams, paramsToFilters } from "../lib/urlState"; import { useUrlMirror } from "../lib/useUrlMirror"; import { accountKey, LS, readJSON, writeJSON } from "../lib/storage"; +import { logFilterChange } from "../lib/filterLog"; import { useNavigation } from "./NavigationProvider"; // Owns the GLOBAL feed-filter state (the feed's scope/tags/content/sort/show), lifted out of the App @@ -123,6 +124,7 @@ export function FeedFiltersProvider({ children }: { children: ReactNode }) { const setFilters = useCallback((next: FeedFilters) => { setFiltersState(next); + logFilterChange("feed", next, next.q); // Persist under THIS tab's active account so filters don't bleed between accounts. const key = accountKey(FILTERS_KEY, getActiveAccount()); if (key) writeJSON(key, next); diff --git a/frontend/src/components/LibraryPlayer.tsx b/frontend/src/components/LibraryPlayer.tsx index 56d12f30..dfb81095 100644 --- a/frontend/src/components/LibraryPlayer.tsx +++ b/frontend/src/components/LibraryPlayer.tsx @@ -1,9 +1,10 @@ -import { useMemo } from "react"; +import { useCallback, useMemo } from "react"; import { useTranslation } from "react-i18next"; import Modal from "./ui/Modal"; import { api, type DownloadJob } from "../lib/api"; import { jobTitle } from "./downloadRow"; import { exposeVideoToBackgroundPlay } from "../lib/browserBackgroundPlay"; +import { useMediaLogRef } from "../lib/mediaLog"; // E7 S4b — in-app player for a completed library item. We do NOT reuse PlayerModal (a cross-origin // YouTube IFrame shell) or PlexPlayer (a Plex HLS/session shell): both are bound to their own domain @@ -30,6 +31,14 @@ export default function LibraryPlayer({ job, onClose }: { job: DownloadJob; onCl // Our self-hosted poster (always same-origin, never expires) is the primary; the source thumbnail is // the fallback. Same precedence as the library-row thumbnail. const poster = job.poster_url ? api.posterImageUrl(job.id) : (asset?.thumbnail_url ?? undefined); + const logMedia = useMediaLogRef("library"); + const videoRef = useCallback( + (el: HTMLVideoElement | null) => { + exposeVideoToBackgroundPlay(el); + logMedia(el); + }, + [logMedia], + ); return ( @@ -42,13 +51,13 @@ export default function LibraryPlayer({ job, onClose }: { job: DownloadJob; onCl className="w-40 h-40 rounded-xl object-cover border border-border" /> ) : null} -