From 293a14361aa8c940f69dae234d3f35b177bcd7e0 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Thu, 30 Jul 2026 12:53:57 -0400 Subject: [PATCH] fix(db): bind datetimes, not strings, when filtering timestamptz columns MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes #1727 and #2257 — the same bug in two services written months apart. AppLog.created_at is `timestamp with time zone`. asyncpg binds a Python str as VARCHAR and Postgres has no `timestamptz >= text` operator, so both of these raised when Postgres planned the query: notifications.check_due_tasks AppLog.created_at >= today.isoformat() logging.get_logs AppLog.created_at >= #1727 was the worse of the two because a per-user `except Exception` swallowed it: reminder emails silently never sent, and the only outward trace was an hourly traceback in the Postgres log. It has been open since 2026-07-19 with the diagnosis written and the fix never applied. #2257 has no swallowing handler, so it merely breaks the admin log viewer's date filters outright. notifications: `utc_day_start(day)` returns midnight UTC as an AWARE datetime. Deliberately not the bare `date` the original diagnosis suggested — comparing timestamptz to date does work via an implicit cast, but Postgres resolves that cast in the SESSION's TimeZone, so the dedup window would drift with a server setting nobody remembers is load-bearing. logging: `parse_filter_datetime()` converts the query-string value to an aware UTC datetime; unparseable input returns None so the filter is skipped rather than 500ing the viewer. It also fixes a bug the naive fix would have introduced — `date_to=2026-07-30` parses to midnight, so `<=` would exclude the entire day the user asked for. Date-only upper bounds now run to 23:59:59.999999, while a value carrying an explicit time is left as given. The guard is the point. This class is invisible to ordinary testing: the failure happens when Postgres plans the query, not when Python builds it, so no unit test that doesn't execute SQL can see it. tests/test_timestamp_filters.py fails CI on two shapes — 1. a local bound to .isoformat() compared against a *_at column (#1727) 2. a str-ANNOTATED PARAMETER compared against a *_at column (#2257) Shape 2 is the one that matters. Nothing in logging.py looks date-ish, so a guard built only from #1727's shape finds nothing there — which is exactly how the second instance survived. Verified by replaying both checks against the pre-fix files out of git: shape 1 catches `today_str`, shape 2 catches `date_from`/`date_to`, and the current tree is clean. Found by grepping for siblings after fixing #1727 — the third instance today of "the second place nobody checked", after #2245. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01UaYUaouG9jjhATyuxCKrQs --- src/scribe/services/logging.py | 46 +++++++-- src/scribe/services/notifications.py | 26 ++++- tests/test_timestamp_filters.py | 145 +++++++++++++++++++++++++++ 3 files changed, 207 insertions(+), 10 deletions(-) create mode 100644 tests/test_timestamp_filters.py diff --git a/src/scribe/services/logging.py b/src/scribe/services/logging.py index 228e2ee..3123920 100644 --- a/src/scribe/services/logging.py +++ b/src/scribe/services/logging.py @@ -89,6 +89,38 @@ async def log_error( await session.commit() +def parse_filter_datetime(value: str | None, *, end_of_day: bool = False) -> datetime | None: + """An ISO date/datetime from a query string as an AWARE UTC datetime. + + The admin log filters arrive as raw `request.args` strings and used to be + compared straight against `AppLog.created_at`. asyncpg binds a str as + VARCHAR and Postgres has no `timestamptz >= text` operator, so supplying + either date filter raised — the same defect as #1727 in notifications, in a + second place (#2254). + + Returns None for anything unparseable: a malformed filter should narrow + nothing rather than 500 the log viewer. + + `end_of_day` matters for the upper bound. A bare "2026-07-30" parses to + midnight, so `created_at <= that` would exclude the whole of the day the + user asked for — the one day they most likely wanted. With this flag a + date-only value is pushed to the last microsecond of that day; a value that + already carries a time is left exactly as given. + """ + raw = (value or "").strip() + if not raw: + return None + try: + parsed = datetime.fromisoformat(raw) + except ValueError: + return None + if end_of_day and len(raw) == 10: # date-only, no time component + parsed = parsed.replace(hour=23, minute=59, second=59, microsecond=999999) + if parsed.tzinfo is None: + parsed = parsed.replace(tzinfo=timezone.utc) + return parsed + + async def get_logs( category: str | None = None, user_id: int | None = None, @@ -118,12 +150,14 @@ async def get_logs( ) query = query.where(search_filter) count_query = count_query.where(search_filter) - if date_from: - query = query.where(AppLog.created_at >= date_from) - count_query = count_query.where(AppLog.created_at >= date_from) - if date_to: - query = query.where(AppLog.created_at <= date_to) - count_query = count_query.where(AppLog.created_at <= date_to) + start = parse_filter_datetime(date_from) + end = parse_filter_datetime(date_to, end_of_day=True) + if start: + query = query.where(AppLog.created_at >= start) + count_query = count_query.where(AppLog.created_at >= start) + if end: + query = query.where(AppLog.created_at <= end) + count_query = count_query.where(AppLog.created_at <= end) total = (await session.execute(count_query)).scalar() or 0 diff --git a/src/scribe/services/notifications.py b/src/scribe/services/notifications.py index ae84c9f..cd171d6 100644 --- a/src/scribe/services/notifications.py +++ b/src/scribe/services/notifications.py @@ -3,7 +3,7 @@ import asyncio import json import logging -from datetime import date, datetime, timezone +from datetime import date, datetime, time, timezone from sqlalchemy import func, select, text @@ -149,13 +149,25 @@ async def send_invitation_email(email: str, invite_url: str, invited_by_username await send_email(email, "Fabled Scribe - You're Invited!", _email_html("You're Invited!", body)) +def utc_day_start(day: date) -> datetime: + """Midnight UTC on `day`, as an AWARE datetime — the reminder dedup window. + + Deliberately a `datetime` and not the bare `date` (#1727). Comparing a + `timestamptz` column against a `date` does work, via an implicit cast — but + Postgres resolves that cast in the SESSION's TimeZone, so the window would + move with a server setting nobody remembers is load-bearing. An aware UTC + datetime says what it means and compares the same way everywhere. + """ + return datetime.combine(day, time.min, tzinfo=timezone.utc) + + async def check_due_tasks() -> None: """Check for tasks due today and send reminder emails.""" if not await is_smtp_configured(): return today = date.today() - today_str = today.isoformat() + window_start = utc_day_start(today) async with async_session() as session: # Find tasks due today or overdue, not done @@ -188,12 +200,18 @@ async def check_due_tasks() -> None: if not email: continue - # Dedup: check if we already sent a reminder today + # Dedup: check if we already sent a reminder today. + # `window_start` is an aware datetime, NOT `today.isoformat()`. + # asyncpg binds a str as VARCHAR and Postgres has no + # `timestamptz >= text` operator, so this raised on every run + # that got this far — swallowed by the per-user `except` below, + # which is why the only symptom was reminders silently never + # sending plus an hourly traceback in the DB log (#1727). dedup_result = await session.execute( select(func.count(AppLog.id)).where( AppLog.action == "task_reminder", AppLog.user_id == user_id, - AppLog.created_at >= today_str, + AppLog.created_at >= window_start, ) ) if (dedup_result.scalar() or 0) > 0: diff --git a/tests/test_timestamp_filters.py b/tests/test_timestamp_filters.py new file mode 100644 index 0000000..4f2af64 --- /dev/null +++ b/tests/test_timestamp_filters.py @@ -0,0 +1,145 @@ +"""Timestamp filters must bind datetimes, never strings (#1727, #2254). + +`AppLog.created_at` is `timestamp with time zone`. asyncpg binds a Python `str` +as VARCHAR, and Postgres has no `timestamptz >= text` operator — so comparing +the column against `date.today().isoformat()` or a raw `request.args` string +raises at query time, not at import time and not in any unit test that doesn't +touch a database. + +That is what made this class of bug survive: it is invisible to every test that +doesn't execute the SQL, and in the notifications case the exception was +swallowed by a per-user `except Exception`, so the only outward symptom was +reminder emails silently never sending. + +Found twice in the same afternoon, in two services written months apart, so the +last test here guards the CLASS rather than the two instances. +""" +import ast +import re +from datetime import date, datetime, timezone +from pathlib import Path + +SRC = Path(__file__).resolve().parents[1] / "src" / "scribe" + + +# --- #1727: the reminder dedup window ---------------------------------------- + +def test_utc_day_start_is_an_aware_datetime_not_a_string(): + from scribe.services.notifications import utc_day_start + + start = utc_day_start(date(2026, 7, 30)) + assert isinstance(start, datetime) + assert not isinstance(start, str) + # Aware, and pinned to UTC rather than whatever the DB session's TimeZone + # happens to be — a bare `date` would resolve midnight server-side. + assert start.tzinfo is not None + assert start.utcoffset() == timezone.utc.utcoffset(None) + assert (start.year, start.month, start.day) == (2026, 7, 30) + assert (start.hour, start.minute, start.second, start.microsecond) == (0, 0, 0, 0) + + +# --- #2254: the admin log viewer's date filters ------------------------------ + +def test_filter_datetime_parses_dates_and_datetimes_to_aware_utc(): + from scribe.services.logging import parse_filter_datetime + + d = parse_filter_datetime("2026-07-30") + assert isinstance(d, datetime) and d.tzinfo is not None + assert (d.hour, d.minute) == (0, 0) + + # An explicit time is honoured, not overwritten. + dt = parse_filter_datetime("2026-07-30T14:35:00") + assert (dt.hour, dt.minute) == (14, 35) + + # Already-aware input keeps its offset rather than being stamped UTC. + aware = parse_filter_datetime("2026-07-30T14:35:00+02:00") + assert aware.utcoffset().total_seconds() == 2 * 3600 + + +def test_filter_datetime_upper_bound_covers_the_whole_requested_day(): + """`date_to=2026-07-30` must INCLUDE that day. Parsed as bare midnight it + would exclude every event on the one day the user asked for.""" + from scribe.services.logging import parse_filter_datetime + + end = parse_filter_datetime("2026-07-30", end_of_day=True) + assert (end.hour, end.minute, end.second) == (23, 59, 59) + assert end.microsecond == 999999 + + # But a value that already carries a time is left alone — the caller meant it. + exact = parse_filter_datetime("2026-07-30T09:00:00", end_of_day=True) + assert (exact.hour, exact.minute, exact.second) == (9, 0, 0) + + +def test_filter_datetime_rejects_garbage_instead_of_raising(): + """A malformed filter should narrow nothing, not 500 the log viewer.""" + from scribe.services.logging import parse_filter_datetime + + for junk in ("", " ", None, "not-a-date", "2026-13-45", "yesterday"): + assert parse_filter_datetime(junk) is None + + +# --- the class-level guard --------------------------------------------------- + +def _timestamp_comparison_offenders() -> list[str]: + """Every place a `*_at` column is compared against a known-string name. + + TWO shapes, because the two real bugs had different ones and a guard built + from only the first would have missed the second: + + 1. a local bound to `.isoformat()` — #1727, `today_str = today.isoformat()` + 2. a parameter annotated `str` — #2254, `date_from: str | None`, straight + off `request.args`, never touching + isoformat at all + + Shape 2 is the nastier one: nothing in the file looks date-ish, so grepping + for isoformat finds nothing. It was caught by reading, not by tooling — + which is exactly why it belongs in tooling now. + + Deliberately narrow on both. A blanket "no strings near SQL" rule would fire + on every to_dict() in the codebase and get muted, and a muted guard is worse + than none. + """ + offenders: list[str] = [] + files = sorted((SRC / "services").rglob("*.py")) + sorted((SRC / "routes").rglob("*.py")) + + for path in files: + src = path.read_text() + rel = path.relative_to(SRC) + + suspect_names: dict[str, str] = {} + + # Shape 1 — locals bound to an isoformat() result. + for name in re.findall(r"^\s*(\w+)\s*=\s*[\w.()]+\.isoformat\(\)", src, re.M): + suspect_names[name] = "an isoformat() string" + + # Shape 2 — parameters annotated as str (incl. `str | None`, Optional[str]). + try: + tree = ast.parse(src) + except SyntaxError: # pragma: no cover - not our concern here + tree = None + if tree is not None: + for node in ast.walk(tree): + if not isinstance(node, (ast.FunctionDef, ast.AsyncFunctionDef)): + continue + args = node.args + for arg in [*args.posonlyargs, *args.args, *args.kwonlyargs]: + if arg.annotation is None: + continue + ann = ast.unparse(arg.annotation) + if re.fullmatch(r"(?:Optional\[)?str\]?(?:\s*\|\s*None)?", ann): + suspect_names[arg.arg] = f"a str-annotated parameter ({ann})" + + for name, why in suspect_names.items(): + if re.search(rf"\w*_at\s*(?:>=|<=|>|<)\s*{re.escape(name)}\b", src): + offenders.append(f"{rel}: timestamp column compared against `{name}` — {why}") + + return offenders + + +def test_no_service_compares_a_timestamp_column_against_a_string(): + offenders = _timestamp_comparison_offenders() + assert not offenders, ( + "asyncpg binds a str as VARCHAR and Postgres has no `timestamptz >= text` " + "operator, so this raises at query time — invisible to any test that " + "doesn't execute the SQL:\n " + "\n ".join(offenders) + )