fix(db): bind datetimes, not strings, when filtering timestamptz columns
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 9s
CI & Build / TypeScript typecheck (push) Successful in 10s
CI & Build / integration (push) Successful in 16s
CI & Build / Python tests (push) Successful in 42s
CI & Build / Build & push image (push) Successful in 26s
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 9s
CI & Build / TypeScript typecheck (push) Successful in 10s
CI & Build / integration (push) Successful in 16s
CI & Build / Python tests (push) Successful in 42s
CI & Build / Build & push image (push) Successful in 26s
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 >= <raw request.args str> #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) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01UaYUaouG9jjhATyuxCKrQs
This commit is contained in:
@@ -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
|
||||
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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)
|
||||
)
|
||||
Reference in New Issue
Block a user