feat: Settings → Diagnostics, a consented log level and the tab's own log
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.
This commit is contained in:
@@ -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")
|
||||
@@ -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
|
||||
|
||||
+4
-2
@@ -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
|
||||
|
||||
|
||||
@@ -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)
|
||||
+131
-19
@@ -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
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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")
|
||||
|
||||
@@ -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)}
|
||||
@@ -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)}
|
||||
|
||||
@@ -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):
|
||||
|
||||
@@ -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
|
||||
Reference in New Issue
Block a user