peter
0b672ed6e7
- A failure keeps its traceback unless it is yt-dlp's or our own StatedFailure (a message that is the whole story). A plain RuntimeError, RecursionError or OSError is also what a bug of ours raises, and its stack is the only lead. - The stack is scrubbed link by link (logs.scrubbed_stack): a chained DownloadError under a DB error no longer prints yt-dlp's text unscrubbed. - Engine hide_parameters: a DB error's message no longer carries the title or path it was writing. - The download and edit failure lines go out even when their DB write fails. - The worker's child_exit/crash/supervisor lines say download.job.failed only when the job failed there; a crash the DB will not record no longer ends the thread. Stopping a paused child is download.child.stopped, not a second abort. - log_safe also covers generic ids with spaces, playlist titles and bare ids. - The ffmpeg image steps log the failure kind, not the argv with its path. - The consent contract accepts only the body of a plain consented_trace() check, and any level that may be TRACE. - Tests for each; every one mutation-checked.
408 lines
15 KiB
Python
408 lines
15 KiB
Python
"""E22.5 S1 — what a log line may NOT carry.
|
|
|
|
`logs.redact_text` is a safety net over addresses and credential params, and it was doing the whole
|
|
job: every one of these call sites was putting user content into a line and relying on the net to
|
|
catch it. Two things were wrong with that. What the net does NOT cover went in whole — a search
|
|
term, a source URL, an upstream body that quotes the request back — and what it DOES cover came out
|
|
as `[email]`, so the line's one variable was a constant and the line said nothing.
|
|
|
|
The cases below pin the call sites. The last one pins the family: no future log call may pass the
|
|
same kind of value without saying, on the line, why it is safe.
|
|
"""
|
|
|
|
import ast
|
|
import json
|
|
import logging
|
|
import pathlib
|
|
|
|
import httpx
|
|
import pytest
|
|
|
|
from app import logs
|
|
from app.youtube.client import YouTubeError, _upstream_failure
|
|
|
|
TERM = "the exact thing they typed"
|
|
|
|
|
|
class _Sink(logging.Handler):
|
|
"""The stdout handler's own filter and formatter, so a case sees the bytes a deployment writes
|
|
— not the record before redaction ran."""
|
|
|
|
def __init__(self):
|
|
super().__init__(level=logging.NOTSET)
|
|
self.lines: list[str] = []
|
|
self.setFormatter(logs.JsonFormatter())
|
|
self.addFilter(logs.ContextFilter())
|
|
|
|
def emit(self, record):
|
|
self.lines.append(self.format(record))
|
|
|
|
def objects(self) -> list[dict]:
|
|
return [json.loads(line) for line in self.lines]
|
|
|
|
def at(self, level: str) -> list[dict]:
|
|
return [o for o in self.objects() if o["level"] == level]
|
|
|
|
|
|
@pytest.fixture
|
|
def sink():
|
|
logger = logging.getLogger("siftlode")
|
|
handler = _Sink()
|
|
previous = logger.level
|
|
logger.addHandler(handler)
|
|
logger.setLevel(logs.TRACE)
|
|
try:
|
|
yield handler
|
|
finally:
|
|
logger.removeHandler(handler)
|
|
logger.setLevel(previous)
|
|
|
|
|
|
def _youtube_403(term: str) -> httpx.Response:
|
|
"""A real-shaped Data API error. `message` is prose, and prose from an upstream quotes the
|
|
request back — which is how a search term ends up in our log through someone else's words."""
|
|
return httpx.Response(
|
|
403,
|
|
json={
|
|
"error": {
|
|
"code": 403,
|
|
"message": f"The request for '{term}' cannot be completed: quota exceeded.",
|
|
"errors": [{"reason": "quotaExceeded", "domain": "youtube.quota"}],
|
|
}
|
|
},
|
|
request=httpx.Request("GET", "https://www.googleapis.com/youtube/v3/search"),
|
|
)
|
|
|
|
|
|
def test_an_upstream_failure_logs_the_reason_code_and_not_the_body(sink):
|
|
err = _upstream_failure("GET", "search", _youtube_403(TERM))
|
|
|
|
(line,) = sink.at("WARNING")
|
|
assert line["attrs"]["reason"] == "quotaExceeded"
|
|
assert line["attrs"]["status"] == 403
|
|
assert TERM not in json.dumps(line)
|
|
# The error is raised to callers that put it in a log line of their own (routes/channels.py)
|
|
# and in a 422 answered to the user, so the body must not travel in it either.
|
|
assert TERM not in str(err)
|
|
assert err.reason == "quotaExceeded"
|
|
|
|
|
|
@pytest.fixture
|
|
def consented():
|
|
"""The request scope of a user who turned Teljes (TRACE) on for themselves."""
|
|
scope = logs._RequestScope()
|
|
scope.user_id, scope.level = 7, logs.TRACE
|
|
token = logs._scope.set(scope)
|
|
try:
|
|
yield
|
|
finally:
|
|
logs._scope.reset(token)
|
|
|
|
|
|
def test_the_body_is_kept_for_the_one_user_who_consented_to_it(sink, consented):
|
|
_upstream_failure("GET", "search", _youtube_403(TERM))
|
|
|
|
# The diagnostic is not lost, it is gated — on the consent the privacy policy describes.
|
|
(trace,) = sink.at("TRACE")
|
|
assert TERM in trace["attrs"]["body"]
|
|
|
|
|
|
def test_a_process_running_at_trace_is_not_anyones_consent(sink):
|
|
"""`sink` runs the whole tree at TRACE — what an admin setting `log_level` to TRACE does. That
|
|
buys more detail, not every user's search terms quoted back (`logs._traced`)."""
|
|
_upstream_failure("GET", "search", _youtube_403(TERM))
|
|
|
|
assert sink.at("TRACE") == []
|
|
assert TERM not in json.dumps(sink.objects())
|
|
|
|
|
|
def test_a_scope_with_no_elevation_is_not_consent():
|
|
scope = logs._RequestScope()
|
|
scope.user_id = 7
|
|
token = logs._scope.set(scope)
|
|
try:
|
|
assert not logs.consented_trace()
|
|
finally:
|
|
logs._scope.reset(token)
|
|
assert not logs.consented_trace() # a scheduler thread: no request at all
|
|
|
|
|
|
def test_a_refused_token_refresh_names_the_oauth_reason_and_not_its_prose(sink, monkeypatch):
|
|
"""The token endpoint's error is `{"error": "<code>", "error_description": <prose>}` — not the
|
|
Data API's shape. The refresh goes through the same door, so it gets the same treatment."""
|
|
from types import SimpleNamespace
|
|
|
|
from app.youtube import client as yt
|
|
|
|
resp = httpx.Response(
|
|
400,
|
|
json={"error": "invalid_grant", "error_description": "Token has been expired or revoked."},
|
|
request=httpx.Request("POST", "https://oauth2.googleapis.com/token"),
|
|
)
|
|
client = yt.YouTubeClient.__new__(yt.YouTubeClient) # no HTTP client: `_send` is the stub
|
|
client.db = None
|
|
client.user = SimpleNamespace(
|
|
token=SimpleNamespace(access_token=None, expiry=None, refresh_token_enc=b"x")
|
|
)
|
|
monkeypatch.setattr(yt, "decrypt_optional", lambda value: None)
|
|
monkeypatch.setattr(yt, "decrypt", lambda value: "a-refresh-token")
|
|
monkeypatch.setattr(yt.sysconfig, "get_str", lambda db, key: "")
|
|
monkeypatch.setattr(client, "_send", lambda *a, **k: resp)
|
|
|
|
with pytest.raises(YouTubeError) as caught:
|
|
client._access_token()
|
|
err = caught.value
|
|
|
|
(line,) = sink.at("WARNING")
|
|
assert line["attrs"]["reason"] == "invalid_grant"
|
|
assert err.reason == "invalid_grant"
|
|
assert "revoked" not in str(err) and "revoked" not in json.dumps(line)
|
|
|
|
|
|
def test_an_unparseable_body_still_names_the_status(sink):
|
|
"""A proxy answering HTML has no `reason` to take — the line must still be worth reading, and
|
|
must still not fall back to printing the body."""
|
|
resp = httpx.Response(
|
|
502,
|
|
text="<html><body>Bad Gateway</body></html>",
|
|
request=httpx.Request("GET", "https://www.googleapis.com/youtube/v3/search"),
|
|
)
|
|
err = _upstream_failure("GET", "search", resp)
|
|
|
|
(line,) = sink.at("WARNING")
|
|
assert line["attrs"] == {
|
|
"method": "GET",
|
|
"path": "search",
|
|
"status": 502,
|
|
"reason": "<unparseable>",
|
|
}
|
|
assert "Bad Gateway" not in str(err)
|
|
assert isinstance(err, YouTubeError)
|
|
|
|
|
|
def test_a_sign_in_names_the_account_by_id_and_not_by_address(client, make_user, sink):
|
|
make_user(email="signing.in@example.com", password="correct horse battery")
|
|
|
|
r = client.post(
|
|
"/auth/password-login",
|
|
json={"email": "signing.in@example.com", "password": "correct horse battery"},
|
|
)
|
|
assert r.status_code == 200
|
|
|
|
(line,) = [o for o in sink.at("INFO") if o.get("event") == "auth.login.ok"]
|
|
assert line["attrs"]["method"] == "password"
|
|
assert isinstance(line["attrs"]["uid"], int)
|
|
# Not `[email]` either: the redacted form is what made the old line useless.
|
|
assert "signing.in" not in json.dumps(line)
|
|
assert logs.REDACTED_EMAIL not in json.dumps(line)
|
|
|
|
|
|
# --- the family ------------------------------------------------------------------------------
|
|
# Names that hold something a person typed or a place they went. A log call may still pass one —
|
|
# `main.py` logs the instance's OWN setup URL — but it has to say so on the line, which is the
|
|
# difference between a decision and an oversight.
|
|
_BANNED_NAMES = frozenset(
|
|
{
|
|
"term",
|
|
"q",
|
|
"query",
|
|
"search_term",
|
|
"email",
|
|
"emails",
|
|
"recipients",
|
|
"recipient",
|
|
"url",
|
|
"webpage_url",
|
|
"source_url",
|
|
"source_webpage_url",
|
|
"password",
|
|
# A download's path is built from its channel and its title (`storage.rel_path`), so it
|
|
# names what someone downloaded exactly as the URL does. Log the asset id.
|
|
"rel",
|
|
"rel_path",
|
|
"title",
|
|
}
|
|
)
|
|
_BANNED_ATTRS = frozenset(
|
|
{"text", "content", "email", "url", "query", "rel_path", "title", "display_name"}
|
|
)
|
|
_ESCAPE = "log-pii-ok"
|
|
_LOG_METHODS = frozenset(
|
|
{"debug", "info", "warning", "warn", "error", "exception", "critical", "log"}
|
|
)
|
|
|
|
|
|
def _is_log_call(node: ast.AST) -> bool:
|
|
if not isinstance(node, ast.Call) or not isinstance(node.func, ast.Attribute):
|
|
return False
|
|
if node.func.attr not in _LOG_METHODS:
|
|
return False
|
|
base, name = node.func.value, ""
|
|
while isinstance(base, ast.Attribute):
|
|
name = f"{base.attr}.{name}"
|
|
base = base.value
|
|
if isinstance(base, ast.Name):
|
|
name = f"{base.id}.{name}"
|
|
return "log" in name.lower()
|
|
|
|
|
|
def _offending(node: ast.Call) -> set[str]:
|
|
found: set[str] = set()
|
|
for sub in ast.walk(node):
|
|
if isinstance(sub, ast.Name) and sub.id in _BANNED_NAMES:
|
|
found.add(sub.id)
|
|
elif isinstance(sub, ast.Attribute) and sub.attr in _BANNED_ATTRS:
|
|
found.add(f".{sub.attr}")
|
|
return found
|
|
|
|
|
|
def test_no_log_call_passes_what_a_person_typed():
|
|
root = pathlib.Path(__file__).resolve().parents[1] / "app"
|
|
offenders = []
|
|
for path in sorted(root.rglob("*.py")):
|
|
src = path.read_text(encoding="utf-8")
|
|
lines = src.splitlines()
|
|
for node in ast.walk(ast.parse(src)):
|
|
if not _is_log_call(node):
|
|
continue
|
|
names = _offending(node)
|
|
if not names:
|
|
continue
|
|
# The call's own lines plus the one directly above it — a marker belongs either
|
|
# on the argument or on the comment line introducing the call, and nowhere
|
|
# further, or one call's justification would excuse its neighbour.
|
|
start = max(0, node.lineno - 2)
|
|
span = " ".join(lines[start : (node.end_lineno or node.lineno)])
|
|
if _ESCAPE in span:
|
|
continue
|
|
offenders.append(f"{path.relative_to(root)}:{node.lineno} {sorted(names)}")
|
|
assert offenders == [], (
|
|
"a log call carries user-typed content; log an id or a reason code instead, or mark "
|
|
f"the argument (or the line directly above the call) `# {_ESCAPE}: <why it is "
|
|
f"safe>` — {offenders}"
|
|
)
|
|
|
|
|
|
_AT_LEAST_DEBUG = {"DEBUG", "INFO", "WARNING", "WARN", "ERROR", "CRITICAL", "FATAL"}
|
|
|
|
|
|
def _may_run_at_trace(call: ast.Call) -> bool:
|
|
"""A `log.log(level, …)` whose level is not provably DEBUG or above: `logs.TRACE`, a bare
|
|
`TRACE`, a literal 5 — or a variable, which could be any of them."""
|
|
if call.func.attr != "log" or not call.args:
|
|
return False
|
|
level = call.args[0]
|
|
if isinstance(level, ast.Attribute | ast.Name):
|
|
return (level.attr if isinstance(level, ast.Attribute) else level.id) not in _AT_LEAST_DEBUG
|
|
if isinstance(level, ast.Constant) and isinstance(level.value, int):
|
|
return level.value < logging.DEBUG
|
|
return True
|
|
|
|
|
|
def _is_consent_check(test: ast.expr) -> bool:
|
|
"""Exactly `…consented_trace()`: not `not …`, not `x or …` — each of those runs the body when
|
|
there is no consent."""
|
|
return (
|
|
isinstance(test, ast.Call)
|
|
and isinstance(test.func, ast.Attribute | ast.Name)
|
|
and (test.func.attr if isinstance(test.func, ast.Attribute) else test.func.id)
|
|
== "consented_trace"
|
|
)
|
|
|
|
|
|
def _guarded_by_consent(node: ast.AST, parents: dict[ast.AST, ast.AST]) -> bool:
|
|
"""The node runs only inside the BODY of an `if <consented_trace()>:` — not its `else`."""
|
|
while node in parents:
|
|
parent = parents[node]
|
|
if isinstance(parent, ast.If) and _is_consent_check(parent.test) and node in parent.body:
|
|
return True
|
|
node = parent
|
|
return False
|
|
|
|
|
|
def _parents(tree: ast.AST) -> dict[ast.AST, ast.AST]:
|
|
return {child: node for node in ast.walk(tree) for child in ast.iter_child_nodes(node)}
|
|
|
|
|
|
_GATE_SHAPES = {
|
|
"the body of the check": ("if logs.consented_trace():\n log.log(logs.TRACE, 'x')", True),
|
|
"its else": (
|
|
"if logs.consented_trace():\n pass\nelse:\n log.log(logs.TRACE, 'x')",
|
|
False,
|
|
),
|
|
"a negated check": ("if not logs.consented_trace():\n log.log(logs.TRACE, 'x')", False),
|
|
"an or": ("if debug or logs.consented_trace():\n log.log(logs.TRACE, 'x')", False),
|
|
"a nested block in the body": (
|
|
"if logs.consented_trace():\n for t in ts:\n log.log(logs.TRACE, 'x')",
|
|
True,
|
|
),
|
|
}
|
|
|
|
|
|
@pytest.mark.parametrize("shape", list(_GATE_SHAPES))
|
|
def test_the_consent_gate_is_the_body_of_the_check_and_nothing_else(shape):
|
|
src, gated = _GATE_SHAPES[shape]
|
|
tree = ast.parse(src)
|
|
(call,) = [n for n in ast.walk(tree) if isinstance(n, ast.Call) and _is_log_call(n)]
|
|
assert _guarded_by_consent(call, _parents(tree)) is gated
|
|
|
|
|
|
@pytest.mark.parametrize(
|
|
("level", "trace"),
|
|
[
|
|
("logs.TRACE", True),
|
|
("TRACE", True),
|
|
("5", True),
|
|
("level", True),
|
|
("levels[scope]", True),
|
|
("logging.DEBUG", False),
|
|
("logging.WARNING", False),
|
|
("20", False),
|
|
],
|
|
)
|
|
def test_a_level_that_may_be_trace_is_treated_as_trace(level, trace):
|
|
(call,) = [n for n in ast.walk(ast.parse(f"log.log({level}, 'x')")) if isinstance(n, ast.Call)]
|
|
assert _may_run_at_trace(call) is trace
|
|
|
|
|
|
def test_every_escaped_trace_line_is_gated_on_the_users_own_consent():
|
|
"""`log-pii-ok` on a TRACE line means "this is what the user's Teljes consent is for". The TRACE
|
|
level alone does not hold that promise: an admin can run the whole process at TRACE, and a
|
|
scheduler thread has no user at all. So the line must sit under `logs.consented_trace()`."""
|
|
root = pathlib.Path(__file__).resolve().parents[1] / "app"
|
|
offenders = []
|
|
for path in sorted(root.rglob("*.py")):
|
|
src = path.read_text(encoding="utf-8")
|
|
lines = src.splitlines()
|
|
tree = ast.parse(src)
|
|
parents = _parents(tree)
|
|
for node in ast.walk(tree):
|
|
if not _is_log_call(node) or not _offending(node):
|
|
continue
|
|
span = " ".join(lines[max(0, node.lineno - 2) : (node.end_lineno or node.lineno)])
|
|
if (
|
|
_may_run_at_trace(node)
|
|
and _ESCAPE in span
|
|
and not _guarded_by_consent(node, parents)
|
|
):
|
|
offenders.append(f"{path.relative_to(root)}:{node.lineno}")
|
|
assert offenders == [], (
|
|
f"a TRACE line with user content is not under consented_trace(): {offenders}"
|
|
)
|
|
|
|
|
|
def test_a_database_error_does_not_carry_the_values_it_was_given(db):
|
|
"""DB lane. A failed write's message is logged and stored as the job's error text; with its
|
|
bound parameters in it, that is the title or the file path the row was about."""
|
|
from sqlalchemy import exc as sa_exc
|
|
from sqlalchemy import text
|
|
|
|
# Postgres's own text for this one names no value ("value too long for type character
|
|
# varying(3)"), so what is left to leak is SQLAlchemy's `[parameters: …]` suffix.
|
|
db.execute(text("CREATE TEMP TABLE pii_probe (x varchar(3))"))
|
|
with pytest.raises(sa_exc.DBAPIError) as caught:
|
|
db.execute(text("INSERT INTO pii_probe VALUES (:v)"), {"v": "A_Private_Title"})
|
|
db.rollback()
|
|
assert "value too long" in str(caught.value)
|
|
assert "A_Private_Title" not in str(caught.value)
|