peter
6cb8231a9f
The server now logs polled reads at DEBUG, and the browser's copy of each request line promises the server's level: at INFO the unread-count polls filled My log within minutes and, at Detailed, the shipped log. The server marks a line it logged at DEBUG with X-Log-Quiet, so the polled-route list stays in one place.
804 lines
36 KiB
Python
804 lines
36 KiB
Python
"""Structured logging for every Siftlode process — the ONE place logging is configured.
|
|
|
|
Before this module a single deployment printed FOUR different log formats: uvicorn's
|
|
`log_config.json` for the API, a hand-rolled StreamHandler in `main.py` for everything that did not
|
|
start under uvicorn (tests, scripts), `logging.basicConfig()` in the worker and in the download
|
|
child (no timestamp at all), and alembic's `fileConfig`. None of them carried a correlation id, and
|
|
uvicorn's access log printed the query string of every request (`?account=1`, `?source=feed`) — so
|
|
the logs were both unjoinable and leaky. `configure_logging()` replaces all four.
|
|
|
|
Event shape — the OpenTelemetry log data model, without the SDK; one JSON object per line:
|
|
ts · level · sev · source · logger · event · msg · attrs
|
|
plus whatever correlation the context carries (`request_id`, `user_id`, `debug_session_id`,
|
|
`job_id`) and the app version. That shape is what E22.6's admin console filters on and what a Gitea
|
|
issue attachment will carry, so it is deliberately flat and stable.
|
|
|
|
Call sites stay ordinary stdlib logging:
|
|
|
|
log = logs.get_logger(__name__) # app/downloads/pipeline.py -> siftlode.downloads.pipeline
|
|
log.info("job finished", extra=logs.event("download.job.done", job_id=7, bytes=n))
|
|
|
|
`event()` is optional — a bare `log.info("…")` still comes out well-formed — but the dotted code is
|
|
what makes a line queryable later, so add one wherever the line matters.
|
|
|
|
REDACTION IS APPLIED AT THE HANDLER, not at the call site: every message, every attr value and
|
|
every traceback passes `redact()` on the way out. That is the whole point — a secret cannot be
|
|
leaked by forgetting to redact it at one of ~125 call sites, and a new call site is safe by
|
|
default. Never logged, at any level: passwords, tokens (session, reset/verify, setup, share,
|
|
OAuth), cookie blobs, secret config values, and email addresses.
|
|
"""
|
|
|
|
import contextlib
|
|
import contextvars
|
|
import json
|
|
import logging
|
|
import logging.config
|
|
import re
|
|
import sys
|
|
import threading
|
|
import time
|
|
import traceback
|
|
import uuid
|
|
from collections.abc import Callable
|
|
from datetime import datetime, timezone
|
|
from typing import Any
|
|
from urllib.parse import parse_qsl
|
|
|
|
from app.config import settings
|
|
from app.ratelimit import RateLimiter, client_key
|
|
|
|
# One level below DEBUG for the "Teljes / TRACE" diagnostics level (search strings, redacted request
|
|
# bodies). Registered on import so `logging.getLogger(...).log(logs.TRACE, …)` and a `LOG_LEVEL=TRACE`
|
|
# both work in every process, including one that never calls configure_logging (a test).
|
|
TRACE = 5
|
|
logging.addLevelName(TRACE, "TRACE")
|
|
|
|
# OpenTelemetry severity numbers for our level names. Kept beside the level because the number is
|
|
# what a log backend sorts and filters on; the name is for humans reading a terminal.
|
|
SEVERITY: dict[str, int] = {
|
|
"TRACE": 1,
|
|
"DEBUG": 5,
|
|
"INFO": 9,
|
|
"WARNING": 13,
|
|
"ERROR": 17,
|
|
"CRITICAL": 21,
|
|
}
|
|
|
|
# Which process this is. Set by configure_logging; every line carries it so one Loki/DB query can
|
|
# separate the API's view of a job from the worker's.
|
|
_source = "api"
|
|
|
|
|
|
# --- correlation context -------------------------------------------------------------------
|
|
# contextvars, like quota's actor attribution (app/quota.py): set at an entry point, read by the
|
|
# formatter, never threaded through call signatures. A child task copies the context at creation,
|
|
# so anything set before `await call_next(...)` is visible to the whole request.
|
|
_request_id: contextvars.ContextVar[str | None] = contextvars.ContextVar(
|
|
"log_request_id", default=None
|
|
)
|
|
_user_id: contextvars.ContextVar[int | None] = contextvars.ContextVar("log_user_id", default=None)
|
|
_debug_session: contextvars.ContextVar[str | None] = contextvars.ContextVar(
|
|
"log_debug_session", default=None
|
|
)
|
|
_job_id: contextvars.ContextVar[int | None] = contextvars.ContextVar("log_job_id", default=None)
|
|
|
|
_CONTEXT_VARS = {
|
|
"request_id": _request_id,
|
|
"user_id": _user_id,
|
|
"debug_session_id": _debug_session,
|
|
"job_id": _job_id,
|
|
}
|
|
|
|
|
|
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:
|
|
"""Attribute this process's log lines to a download job — for the download CHILD, whose whole
|
|
life is one job (the worker uses `bind()` per job instead, since it juggles several)."""
|
|
_job_id.set(job_id)
|
|
|
|
|
|
@contextlib.contextmanager
|
|
def bind(**fields: Any):
|
|
"""Bind correlation fields for the duration of a block (a worker job, a scheduler run):
|
|
|
|
with logs.bind(job_id=job.id):
|
|
...
|
|
|
|
Unknown field names are ignored rather than raising — a caller binding a field this module does
|
|
not know about is a typo, not a reason to take down a download."""
|
|
tokens = [(_CONTEXT_VARS[k].set(v)) for k, v in fields.items() if k in _CONTEXT_VARS]
|
|
keys = [k for k in fields if k in _CONTEXT_VARS]
|
|
try:
|
|
yield
|
|
finally:
|
|
for key, token in zip(keys, tokens):
|
|
_CONTEXT_VARS[key].reset(token)
|
|
|
|
|
|
def event(code: str, /, **attrs: Any) -> dict[str, Any]:
|
|
"""`extra=` payload for a log call: a stable dotted event code plus structured attributes.
|
|
|
|
Returns a plain dict so it composes with stdlib logging and costs nothing when the level is off
|
|
(the dict is built either way; keep the attrs cheap — no DB reads inside the call).
|
|
|
|
`code` is positional-only so that no attribute name is reserved: `event("x", code=...)` means
|
|
the attribute, not this parameter. Without the `/` it was a TypeError, and `code` is exactly
|
|
the word a caller reaches for when the thing that failed has one of its own."""
|
|
return {"event": code, "attrs": attrs}
|
|
|
|
|
|
# --- redaction -----------------------------------------------------------------------------
|
|
# Substring matching, not exact keys: the same secret travels as `password`, `current_password`,
|
|
# `new_password`, `smtp_password`, `plex_server_token`, `access_token`, … Matching on the PART is
|
|
# what makes a key we have never seen safe by default.
|
|
_SECRET_KEY_PARTS = (
|
|
"password",
|
|
"passphrase",
|
|
"token",
|
|
"secret",
|
|
"cookie",
|
|
"authorization",
|
|
"auth_header",
|
|
"ciphertext",
|
|
"private_key",
|
|
"api_key",
|
|
"apikey",
|
|
"credential",
|
|
"session_key",
|
|
)
|
|
|
|
# Query/fragment parameters that carry a credential in a URL we log (OAuth `code`/`state`, our own
|
|
# `?token=` setup and share links, `#verify=` / `#reset=` fragments).
|
|
_SECRET_PARAM_NAMES = (
|
|
"access_token",
|
|
"refresh_token",
|
|
"id_token",
|
|
"token",
|
|
"code",
|
|
"state",
|
|
"key",
|
|
"secret",
|
|
"password",
|
|
"pwd",
|
|
"sig",
|
|
"signature",
|
|
"verify",
|
|
"reset",
|
|
"setup",
|
|
)
|
|
_SECRET_PARAM_RE = re.compile(
|
|
r"\b((?:" + "|".join(_SECRET_PARAM_NAMES) + r")=)([^&\s\"']+)",
|
|
re.IGNORECASE,
|
|
)
|
|
|
|
# Deliberately loose: over-matching redacts a non-address that looks like one (harmless), while
|
|
# under-matching puts a real address in a log we attach to an issue (not harmless).
|
|
_EMAIL_RE = re.compile(r"[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Za-z]{2,}")
|
|
|
|
REDACTED = "[redacted]"
|
|
# `extra={PERSIST: False}` keeps a line out of the `log_events` table while stdout still gets it —
|
|
# how `log_requests` caps anonymous traffic per client (app/logsink.py reads it).
|
|
PERSIST = "persist"
|
|
REDACTED_EMAIL = "[email]"
|
|
|
|
|
|
def redact_text(text: str) -> str:
|
|
"""Scrub a free-text string: credential-bearing URL params and email addresses."""
|
|
scrubbed = _SECRET_PARAM_RE.sub(lambda m: f"{m.group(1)}{REDACTED}", text)
|
|
return _EMAIL_RE.sub(REDACTED_EMAIL, scrubbed)
|
|
|
|
|
|
def redact_query(query: str) -> str:
|
|
"""Scrub a raw query string. DECODED first: the text rules match what was typed, and a browser
|
|
sends it percent-encoded — `someone%40example.com` is an address `_EMAIL_RE` cannot see. Each
|
|
parameter also goes through the key rules, so `?new_password=` goes as `redact` would drop it."""
|
|
pairs = parse_qsl(query, keep_blank_values=True)
|
|
return "&".join(f"{key}={_redact_param(key, value)}" for key, value in pairs)
|
|
|
|
|
|
def _redact_param(key: str, value: str) -> str:
|
|
"""One decoded `key=value` pair. The parameter-NAME rule is applied to the key here rather than
|
|
left to `_SECRET_PARAM_RE` over the rebuilt pair: that pattern was written for the raw,
|
|
percent-encoded query, where a value holds no literal space, `&` or quote, and its value class
|
|
stops at the first one. On decoded text `?state=a%20b` would keep its tail and `?code=%20abc`
|
|
would not match at all — the whole credential straight into the line."""
|
|
if key.lower() in _SECRET_PARAM_NAMES:
|
|
return REDACTED
|
|
return str(redact(value, key=key))
|
|
|
|
|
|
def redact(value: Any, *, key: str = "") -> Any:
|
|
"""Recursively scrub a structure destined for the log.
|
|
|
|
A value whose KEY names a secret is dropped whole (we never log a prefix of a token — a prefix
|
|
is still a leak and still useless). Everything else is scrubbed as text. Depth is bounded by
|
|
the structures we actually log (attrs dicts), and non-JSON types fall through to `str`."""
|
|
lowered = key.lower()
|
|
if key and any(part in lowered for part in _SECRET_KEY_PARTS):
|
|
return REDACTED
|
|
if isinstance(value, dict):
|
|
return {k: redact(v, key=str(k)) for k, v in value.items()}
|
|
if isinstance(value, (list, tuple)):
|
|
return [redact(v, key=key) for v in value]
|
|
if isinstance(value, str):
|
|
return redact_text(value)
|
|
return value
|
|
|
|
|
|
# --- formatters ----------------------------------------------------------------------------
|
|
_SCRUBBED_STACK = "scrubbed_stack"
|
|
|
|
|
|
def scrubbed_stack(exc: BaseException, scrub: Callable[[BaseException], str]) -> dict[str, str]:
|
|
"""`extra=` fragment: `exc`'s traceback, rendered where an `exc_info` stack goes, with the
|
|
message of every exception in it put through `scrub`.
|
|
|
|
For a failure whose message can name someone's data (a download's URL, a file path, a video
|
|
id). The frames name code and are kept whole; the text at the foot of each link is the data.
|
|
A plain `exc_info` renders the chain too — the `__cause__`/`__context__` a DB error raised
|
|
inside `except DownloadError` carries — so scrubbing only the line's own message is not
|
|
enough. Merge it into the call's `extra`: `{**event(...), **scrubbed_stack(...)}`."""
|
|
links: list[BaseException] = []
|
|
link: BaseException | None = exc
|
|
while link is not None and all(link is not seen for seen in links):
|
|
links.append(link)
|
|
link = link.__cause__ or (None if link.__suppress_context__ else link.__context__)
|
|
parts: list[str] = []
|
|
for i in range(len(links) - 1, -1, -1): # the oldest first, as Python prints a chain
|
|
link = links[i]
|
|
kind = type(link)
|
|
name = kind.__qualname__
|
|
if kind.__module__ not in ("builtins", "__main__"):
|
|
name = f"{kind.__module__}.{name}"
|
|
try:
|
|
message = scrub(link)
|
|
# silent-ok: the message is what could not be rendered, and the placeholder says so — the
|
|
# caller is in the middle of reporting one failure and must not get a second from here.
|
|
except Exception: # noqa: BLE001 — a `__str__` that raises, of any shape
|
|
message = "<unprintable>"
|
|
frames = "".join(traceback.format_tb(link.__traceback__))
|
|
head = f"Traceback (most recent call last):\n{frames}" if frames else ""
|
|
parts.append(f"{head}{name}: {message}" if message else f"{head}{name}")
|
|
if i:
|
|
parts.append(
|
|
"\nThe above exception was the direct cause of the following exception:\n"
|
|
if links[i - 1].__cause__ is link
|
|
else "\nDuring handling of the above exception, another exception occurred:\n"
|
|
)
|
|
return {_SCRUBBED_STACK: "\n".join(parts)}
|
|
|
|
|
|
# Attributes every LogRecord carries; anything else a caller passed via `extra=` is a structured
|
|
# 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, "elevated", _SCRUBBED_STACK}
|
|
)
|
|
|
|
|
|
class ContextFilter(logging.Filter):
|
|
"""Copies the correlation contextvars onto the record. A Filter (not the formatter) so the
|
|
values are captured at emit time, before a QueueHandler can move the record to another
|
|
thread — the DB sink in S3 depends on that."""
|
|
|
|
def filter(self, record: logging.LogRecord) -> bool:
|
|
for name, var in _CONTEXT_VARS.items():
|
|
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 {})
|
|
attrs.update({k: v for k, v in extra.items() if k not in _CONTEXT_VARS})
|
|
return attrs
|
|
|
|
|
|
def _safe_message(record: logging.LogRecord) -> str:
|
|
"""`record.getMessage()` raises if the args don't match the format string. A broken log call
|
|
must not take down the caller, so the failure is reported IN the line instead."""
|
|
try:
|
|
return record.getMessage()
|
|
# silent-ok: the failure is reported IN the returned line. Logging it would re-enter this same
|
|
# formatter with a record built out of the one that just failed.
|
|
except Exception as exc: # noqa: BLE001 — any formatting error, reported not raised
|
|
return f"{record.msg!r} (log formatting failed: {exc})"
|
|
|
|
|
|
def record_fields(record: logging.LogRecord) -> dict[str, Any]:
|
|
"""The event as structured fields, REDACTED — the one definition both the stdout line and the
|
|
`log_events` row are built from, so the two sinks can never disagree about what is safe to keep.
|
|
Absent optional fields are left out; `ts` is an aware datetime."""
|
|
fields: dict[str, Any] = {
|
|
"ts": datetime.fromtimestamp(record.created, timezone.utc),
|
|
"level": record.levelname,
|
|
"sev": SEVERITY.get(record.levelname, 9),
|
|
"source": _source,
|
|
"logger": record.name,
|
|
"msg": redact_text(_safe_message(record)),
|
|
}
|
|
code = getattr(record, "event", None)
|
|
if code:
|
|
fields["event"] = code
|
|
for name in _CONTEXT_VARS:
|
|
value = getattr(record, name, None)
|
|
if value is not None:
|
|
fields[name] = value
|
|
attrs = _record_attrs(record)
|
|
if attrs:
|
|
fields["attrs"] = redact(attrs)
|
|
if record.exc_info:
|
|
fields["exc"] = redact_text(logging.Formatter().formatException(record.exc_info))
|
|
elif getattr(record, _SCRUBBED_STACK, None):
|
|
fields["exc"] = redact_text(getattr(record, _SCRUBBED_STACK))
|
|
elif record.exc_text:
|
|
# A QueueHandler-style hand-off formats the traceback into exc_text and drops exc_info.
|
|
fields["exc"] = redact_text(record.exc_text)
|
|
fields["version"] = settings.app_version
|
|
return fields
|
|
|
|
|
|
class JsonFormatter(logging.Formatter):
|
|
"""One JSON object per line — the shape Loki and the `log_events` table both ingest."""
|
|
|
|
def format(self, record: logging.LogRecord) -> str:
|
|
payload = record_fields(record)
|
|
payload["ts"] = payload["ts"].isoformat(timespec="milliseconds")
|
|
return json.dumps(payload, ensure_ascii=False, default=str)
|
|
|
|
|
|
class TextFormatter(logging.Formatter):
|
|
"""Human-readable single line for a terminal (`LOG_FORMAT=text`): the same content, ordered for
|
|
reading. Redaction applies here too — a dev log is still a log someone pastes into an issue."""
|
|
|
|
def format(self, record: logging.LogRecord) -> str:
|
|
stamp = datetime.fromtimestamp(record.created, timezone.utc).strftime("%H:%M:%S.%f")[:-3]
|
|
head = f"{stamp} {record.levelname:<5} [{record.name}]"
|
|
rid = getattr(record, "request_id", None)
|
|
if rid:
|
|
head += f" {rid}"
|
|
code = getattr(record, "event", None)
|
|
line = f"{head} {code + ' — ' if code else ''}{redact_text(_safe_message(record))}"
|
|
attrs = _record_attrs(record)
|
|
if attrs:
|
|
line += f" {json.dumps(redact(attrs), ensure_ascii=False, default=str)}"
|
|
if record.exc_info:
|
|
line += "\n" + redact_text(self.formatException(record.exc_info))
|
|
elif getattr(record, _SCRUBBED_STACK, None):
|
|
line += "\n" + redact_text(getattr(record, _SCRUBBED_STACK))
|
|
return line
|
|
|
|
|
|
# --- configuration -------------------------------------------------------------------------
|
|
# Third-party loggers that are noisy at our own level. Pinned explicitly so the diagnostics knob can
|
|
# lower the ROOT level to DEBUG/TRACE without drowning the output in SQL statements and HTTP chatter
|
|
# — raising THESE is a deliberate, separate act (E22.6's console).
|
|
_THIRD_PARTY_LEVELS = {
|
|
"sqlalchemy": "WARNING",
|
|
"sqlalchemy.engine": "WARNING",
|
|
"apscheduler": "WARNING",
|
|
"urllib3": "WARNING",
|
|
"httpx": "WARNING",
|
|
"httpcore": "WARNING",
|
|
"asyncio": "WARNING",
|
|
"multipart": "WARNING",
|
|
"PIL": "WARNING",
|
|
"alembic": "INFO",
|
|
# uvicorn's own startup/shutdown/WebSocket lines are worth keeping; its ACCESS log is not —
|
|
# it is one line per request with the query string in it, replaced by `log_requests` below.
|
|
"uvicorn": "INFO",
|
|
"uvicorn.error": "INFO",
|
|
"uvicorn.access": "CRITICAL",
|
|
}
|
|
|
|
|
|
def get_logger(name: str) -> logging.Logger:
|
|
"""The logger for one module: `logs.get_logger(__name__)` in `app/plex/sync.py` is
|
|
`siftlode.plex.sync`.
|
|
|
|
The names were literals before, and 25 of them covered 34 modules — six different Plex modules
|
|
all called themselves `siftlode.plex`, so neither a level pinned per logger nor E22.6's console
|
|
filter could tell a sync line from a stream line. Derived from `__name__` there is exactly one
|
|
name per module, it cannot drift from the file it sits in, and `test_logger_names.py` fails if a
|
|
module hand-rolls one again.
|
|
|
|
`__main__` is resolved to the module it really is. The worker runs as `python -m app.worker`
|
|
and spawns `python -m app.downloads.runner`, so in the two long-running processes `__name__`
|
|
is `__main__` — taken at its word, both would log as the bare root. `-m` records the real name
|
|
on the module's spec; a plain script has none and stays the root."""
|
|
if name == "__main__":
|
|
spec = getattr(sys.modules.get("__main__"), "__spec__", None)
|
|
name = getattr(spec, "name", None) or name
|
|
stem = name.removeprefix("app.") if name.startswith("app.") else ""
|
|
# logger-name-ok: this call IS the derivation
|
|
return logging.getLogger(f"siftlode.{stem}" if stem else "siftlode")
|
|
|
|
|
|
def resolve_level(name: str) -> int:
|
|
"""Level name → number. Both ways in (the `LOG_LEVEL` env and the `log_level` admin knob) are
|
|
already held to the `LogLevel` choices, so an unknown name here is a programming error."""
|
|
value = logging.getLevelName(name)
|
|
if not isinstance(value, int):
|
|
raise ValueError(f"unknown log level {name!r}")
|
|
return value
|
|
|
|
|
|
def configure_logging(source: str) -> None:
|
|
"""Configure logging for THIS process. Call once, first thing, in every entry point:
|
|
`main.py` (api), `worker.main`, `downloads/runner.main`, `alembic/env.py`.
|
|
|
|
`source` names the process in every line. The level starts at `LOG_LEVEL` (the bootstrap default);
|
|
the runtime admin knob goes through `set_level()` instead, so changing it needs no restart.
|
|
|
|
Our loggers deliberately keep `propagate=True` and own no handler: everything reaches the single
|
|
root StreamHandler. That is what keeps `caplog` working in tests, and it means a new logger name
|
|
is configured the moment it is created."""
|
|
global _source
|
|
_source = source
|
|
formatter = settings.log_format
|
|
logging.config.dictConfig(
|
|
{
|
|
"version": 1,
|
|
# Never disable loggers created at import time (module-level `getLogger` calls run
|
|
# before this function does).
|
|
"disable_existing_loggers": False,
|
|
"formatters": {
|
|
"json": {"()": f"{__name__}.JsonFormatter"},
|
|
"text": {"()": f"{__name__}.TextFormatter"},
|
|
},
|
|
"filters": {
|
|
"context": {"()": f"{__name__}.ContextFilter"},
|
|
"gate": {"()": f"{__name__}.LevelGate"},
|
|
},
|
|
"handlers": {
|
|
"stdout": {
|
|
"class": "logging.StreamHandler",
|
|
"stream": sys.stdout,
|
|
"formatter": formatter,
|
|
"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."""
|
|
global _base_level
|
|
_base_level = resolve_level(name)
|
|
_apply_root_level(force=True)
|
|
|
|
|
|
def current_level() -> str:
|
|
"""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)
|
|
# The level is SET under the lock too, not just computed: two threads that each computed a
|
|
# different answer would otherwise apply them in either order, and the older one could win —
|
|
# the root back at the base while an elevation is still active.
|
|
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
|
|
|
|
|
|
# --- erased accounts ------------------------------------------------------------------------
|
|
# `auth.purge_user` deletes an account's `log_events` rows, but a line about that account can still
|
|
# be on its way: the erasing request's own access line is logged AFTER the handler committed, a queued
|
|
# row waits for the sink's writer, a background task logs later. Those rows are stored without the
|
|
# account (`logsink` asks here). Remembered for an hour in this process — a line later than that has
|
|
# no request left to come from, and the retention job is the backstop for any other process.
|
|
ERASED_MEMORY_SECONDS = 3600.0
|
|
_erased: dict[int, float] = {}
|
|
_erased_lock = threading.Lock()
|
|
# Held by whoever checks rows against `is_erased` AND writes them (`erasure_guard`). `forget_user`
|
|
# takes it too, so an erasure waits for a write that already passed the check to commit — and the
|
|
# purge's DELETE, which runs after `forget_user`, then removes those rows as well. Without it a row
|
|
# checked a moment before the erasure could be inserted a moment after the DELETE.
|
|
_erasure_guard = threading.Lock()
|
|
|
|
|
|
def erasure_guard() -> threading.Lock:
|
|
"""Hold this around "drop erased accounts from these rows, insert them, commit"."""
|
|
return _erasure_guard
|
|
|
|
|
|
def forget_user(user_id: int) -> None:
|
|
"""Mark `user_id` erased: no line logged about it from now on is stored under its id. Call BEFORE
|
|
deleting its rows (see `_erasure_guard`)."""
|
|
now = time.monotonic()
|
|
with _erasure_guard, _erased_lock:
|
|
for stale in [u for u, at in _erased.items() if now - at > ERASED_MEMORY_SECONDS]:
|
|
del _erased[stale]
|
|
_erased[user_id] = now
|
|
with _elevations_lock:
|
|
_elevations.pop(user_id, None)
|
|
# That pop can have removed the lowest elevation, and the root level is the lowest of the base
|
|
# and every unexpired one. Recomputed here rather than left to whichever later request happens
|
|
# to call `_track_elevation` — the invariant `_apply_root_level` documents holds at every pop.
|
|
_apply_root_level()
|
|
|
|
|
|
def is_erased(user_id: int | None) -> bool:
|
|
if user_id is None:
|
|
return False
|
|
with _erased_lock:
|
|
at = _erased.get(user_id)
|
|
return at is not None and time.monotonic() - at <= ERASED_MEMORY_SECONDS
|
|
|
|
|
|
def current_source() -> str:
|
|
"""The process name `configure_logging` was given (api, worker, runner, alembic)."""
|
|
return _source
|
|
|
|
|
|
# --- request logging -----------------------------------------------------------------------
|
|
# A client may supply its own request id so a browser log line and a server line join up (E22 S4).
|
|
# Accepted only in this shape: it ends up in a log field, and an unbounded header would be a way to
|
|
# write arbitrary text into the log.
|
|
_REQUEST_ID_RE = re.compile(r"^[A-Za-z0-9._-]{8,64}$")
|
|
|
|
# Paths whose success is logged at DEBUG rather than INFO: the container healthcheck runs every 15s
|
|
# (5.7k lines/day saying nothing), hashed static assets are served by the hundred per page load, and
|
|
# the admin log console reads the stored log — its live tail every few seconds, so at INFO the log
|
|
# would fill with the console watching itself. A FAILURE on any of them still logs at WARNING/ERROR
|
|
# — this lowers the floor, it does not hide.
|
|
_QUIET_PREFIXES = ("/healthz", "/assets/", "/static/", "/api/admin/logs")
|
|
|
|
# The reads the frontend POLLS (a `useLiveQuery`, the `me` heartbeat, the sync status, the subtitle
|
|
# progress), by route template, GET only — logged at DEBUG like the prefixes above. One open tab asked
|
|
# for the two unread counts, `/api/me` and the download index every 30 s, and at INFO those were ~95%
|
|
# of the stored log (measured on prod 2026-09-19): 11k lines a day per tab burying every line someone
|
|
# caused. The same route answered with a failure still logs at WARNING/ERROR.
|
|
_POLLED_ROUTES = frozenset(
|
|
{
|
|
"/api/me",
|
|
"/api/me/notifications/unread_count",
|
|
"/api/messages/unread_count",
|
|
"/api/downloads",
|
|
"/api/downloads/index",
|
|
"/api/downloads/usage",
|
|
"/api/sync/my-status",
|
|
"/api/admin/scheduler",
|
|
"/api/admin/downloads",
|
|
"/api/admin/downloads/storage",
|
|
"/api/plex/subtitle/{rating_key}/{sub_ord}/status",
|
|
}
|
|
)
|
|
|
|
# Not `siftlode.logs`: this is the replacement for uvicorn's ACCESS log, and `siftlode.http` is
|
|
# what an operator pins a level on when they want request lines and nothing else. The module it
|
|
# happens to live in is not what the name is about.
|
|
_request_log = logging.getLogger("siftlode.http") # logger-name-ok: named for the traffic
|
|
|
|
|
|
async def log_requests(request, call_next):
|
|
"""The single access-log line, replacing uvicorn's.
|
|
|
|
What changes versus `uvicorn.access`: the ROUTE TEMPLATE instead of the concrete path (so
|
|
`/api/videos/{video_id}` groups), never the query string (it carried `?account=`, and at TRACE
|
|
the redacted query belongs in attrs, not in the URL), a request id echoed back in
|
|
`X-Request-Id` (with the template in `X-Route`), the duration, and the account — read from `request.state`, which the auth
|
|
dependency fills, because this middleware sits outside both the session middleware and the
|
|
downstream task's context."""
|
|
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:
|
|
response = await call_next(request)
|
|
except Exception:
|
|
# The unhandled-exception path: FastAPI's ServerErrorMiddleware re-raises after its own
|
|
# 500, so without this the ONE request that most needs a log line is the one with no
|
|
# access-log entry at all.
|
|
_request_log.exception(
|
|
"request failed",
|
|
extra={
|
|
**event(
|
|
"http.request",
|
|
method=request.method,
|
|
path=_route_template(request),
|
|
duration_ms=round((time.perf_counter() - started) * 1000, 1),
|
|
),
|
|
**_request_owner(request, logging.ERROR),
|
|
},
|
|
)
|
|
_scope.reset(scope_token)
|
|
_request_id.reset(token)
|
|
raise
|
|
duration_ms = round((time.perf_counter() - started) * 1000, 1)
|
|
status = response.status_code
|
|
quiet = request.url.path.startswith(_QUIET_PREFIXES) or (
|
|
request.method == "GET" and _route_template(request) in _POLLED_ROUTES
|
|
)
|
|
if status >= 500:
|
|
level = logging.ERROR
|
|
elif status >= 400:
|
|
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 consented to: the query string too — redacted, and in attrs only, never
|
|
# in the message.
|
|
if request.url.query and _traced(scope):
|
|
attrs["query"] = redact_query(request.url.query)
|
|
_request_log.log(
|
|
level,
|
|
"%s %s %s",
|
|
request.method,
|
|
_route_template(request),
|
|
status,
|
|
extra={**event("http.request", **attrs), **_request_owner(request, level)},
|
|
)
|
|
response.headers["X-Request-Id"] = rid
|
|
# The browser logs its own copy of this line (frontend lib/http.ts) and must pick the same level:
|
|
# it learns "this one is quiet" here instead of keeping a second copy of the polled-route list.
|
|
if level == logging.DEBUG:
|
|
response.headers["X-Log-Quiet"] = "1"
|
|
# The template, so the browser's copy of this line groups the same way (frontend lib/http.ts).
|
|
# Only a MATCHED route's: a template never carries a path parameter's value (a share token stays
|
|
# `{token}`), while the raw-path fallback of an unmatched request could — the browser then
|
|
# templates the path itself.
|
|
matched = _matched_route(request)
|
|
if matched:
|
|
response.headers["X-Route"] = matched
|
|
_scope.reset(scope_token)
|
|
_request_id.reset(token)
|
|
return response
|
|
|
|
|
|
def consented_trace() -> bool:
|
|
"""Whether the current request's OWN user turned Teljes (TRACE) on — the gate for a line that
|
|
carries what they typed or what was quoted back to them. The level alone is not enough: an
|
|
admin running the whole process at TRACE would pass it for every user, and a scheduler thread,
|
|
which has no request, for none of them in particular. Guard such a line with this, then log it
|
|
at TRACE."""
|
|
scope = _scope.get()
|
|
return scope is not None and _traced(scope)
|
|
|
|
|
|
def _traced(scope: _RequestScope) -> bool:
|
|
"""Whether this request's query string is logged: only under its OWN user's Teljes consent. An
|
|
admin setting the whole process to TRACE gets more detail, not every user's search terms — the
|
|
privacy policy promises those are kept only for a user who agreed to it."""
|
|
return scope.level is not None and scope.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
|
|
# 404s is a WARNING that would otherwise land in `log_events` without limit. The client key is an
|
|
# in-memory counter key only; no address is ever written to a log line or a row.
|
|
ANONYMOUS_LINES_PER_MINUTE = 60
|
|
_anonymous_lines = RateLimiter(ANONYMOUS_LINES_PER_MINUTE, 60.0)
|
|
|
|
|
|
def _request_owner(request, level: int) -> dict[str, Any]:
|
|
"""`extra=` fields naming who the request belongs to, and whether its line may be stored. The
|
|
account comes from `request.state` (filled by the auth dependency), so it lands in the line's
|
|
top-level `user_id` — the correlation field — rather than in `attrs`."""
|
|
user_id = getattr(request.state, "user_id", None)
|
|
if user_id is not None:
|
|
return {"user_id": user_id}
|
|
if level < logging.INFO:
|
|
return {} # a quiet line is never stored anyway — don't spend the client's allowance on it
|
|
return {} if _anonymous_lines.allow(client_key(request)) else {PERSIST: False}
|
|
|
|
|
|
def _matched_route(request) -> str | None:
|
|
"""The matched route's template (`/api/videos/{video_id}`), or None when nothing matched."""
|
|
return getattr(request.scope.get("route"), "path", None)
|
|
|
|
|
|
def _route_template(request) -> str:
|
|
"""The matched route's template, else the raw path for a 404 or a static file. Never the query
|
|
string."""
|
|
return _matched_route(request) or request.url.path
|