Fix the 3am notification avalanche and the failing morning digest

Three bugs from the first day of real use. 1. Quiet hours were evaluated in UTC. The router is handed a UTC `now` and compared its hour against "22:00-07:00" directly, so notifications were silenced from 18:00 local -- prime reading time -- and the whole day's budget was released at 03:00 local. The reported avalanche landed at 03:39 and 03:55. Quiet hours are now converted to the reader's wall clock first. 2. The timezone never resolved anyway. TZ was "America/Louisville", which exists on this Arch host but NOT in a Debian container, which ships only the canonical "America/Kentucky/Louisville". The container fell back to UTC and `date` printed "America" as the zone abbreviation. The zone is now read from config rather than the environment, so a bad TZ cannot silently change behaviour, and the compose entry uses the canonical name. NOTE: ~20 other services in compose.yml carry the same bad string; they were left alone since it only affects their log timestamps. 3. Budgets are not a rate. Six notifications fired in a single minute because the daily allowance could all be spent in one cycle. Each lane now has a minimum gap (interest 75min, importance 30min) and sends at most one per cycle, which turns the budget into a rate spread across the day. Separately, the morning digest had silently fallen back to the templated list. The real 28-story payload takes 70.3s to generate against a 60s timeout. Raised to 180s -- and write_prose now LOGS why it failed instead of returning None in silence, which is what made a one-line timeout cost a debugging session.
2026-09-09 09:55:49 -04:00
1 parent 161c518aa7
commit 98bba62976
@@ -113,6 +113,8 @@ class Config:
            "max_alerts_per_group_per_day": r.get("max_alerts_per_group_per_day", 1),
            "important_per_day": r.get("important_per_day", 2),
            "important_per_night": r.get("important_per_night", 1),
+            "interest_min_gap_minutes": r.get("interest_min_gap_minutes", 75),
+            "important_min_gap_minutes": r.get("important_min_gap_minutes", 30),
            "interest_threshold": r.get("interest_threshold", 2.0),
            "important_threshold": r.get("important_threshold", 2.0),
            "digest_floor": r.get("digest_floor", 0.5),
@@ -13,11 +13,14 @@ relevance, importance, vetoes -- is embeddings and arithmetic.
 from __future__ import annotations

 import json
+import logging
 import os
 from dataclasses import dataclass

 import httpx

+logger = logging.getLogger(__name__)
+

@dataclass
 class LlmConfig:
@@ -62,10 +65,14 @@ def _extract_json_object(text: str) -> dict:
 def write_prose(client: httpx.Client, cfg: LlmConfig, stories: list[dict]) -> str | None:
    """One call. Returns None on any failure, and the caller falls back to a
    template -- the digest must never depend on a model being reachable."""
-    if not cfg.enabled or not stories:
+    if not cfg.enabled:
+        logger.info("digest prose disabled in config")
+        return None
+    if not stories:
        return None
    key = os.environ.get(cfg.api_key_env)
    if not key:
+        logger.warning("digest prose skipped: %s is unset", cfg.api_key_env)
        return None
    try:
        resp = client.post(
@@ -88,8 +95,14 @@ def write_prose(client: httpx.Client, cfg: LlmConfig, stories: list[dict]) -> st
        briefing = _extract_json_object(content).get("briefing")
        if isinstance(briefing, str) and briefing.strip():
            return briefing.strip()
-    except Exception:  # noqa: BLE001 - the digest ships regardless
+    except Exception as exc:  # noqa: BLE001 - the digest ships regardless
+        # Fail open, but never silently. The first production digest fell back to
+        # the templated list every morning and the only clue was
+        # "LLM unavailable or disabled" -- the actual cause was a 60s timeout
+        # against a call that takes ~70s, which cost a debugging session to find.
+        logger.warning("digest prose unavailable (%s): %s", type(exc).__name__, exc)
        return None
+    logger.warning("digest prose call returned no usable briefing")
    return None


@@ -19,6 +19,7 @@ from __future__ import annotations
 import sqlite3
 from dataclasses import dataclass
 from datetime import datetime, time, timedelta
+from zoneinfo import ZoneInfo

 from .score import ClusterScore

@@ -41,7 +42,31 @@ def _parse_hhmm(value: str) -> time:
    return time(int(hh), int(mm))


+def local_now(now: datetime, delivery: dict) -> datetime:
+    """UTC instant -> the reader's wall clock.
+
+    Quiet hours and the digest hour are wall-clock decisions, and the router is
+    handed a UTC `now`. Comparing UTC hours against "22:00-07:00" silenced
+    notifications from 18:00 local and released the whole day's budget at 03:00
+    local -- which is exactly the 3:39am avalanche this was reported as.
+
+    The timezone is read from config rather than the TZ environment variable,
+    because TZ fails silently: `America/Louisville` resolves on the Arch host but
+    does NOT exist in a Debian container, where only
+    `America/Kentucky/Louisville` is shipped. The container fell back to UTC and
+    printed "America" as its zone abbreviation.
+    """
+    name = delivery.get("timezone")
+    if not name:
+        return now
+    try:
+        return now.astimezone(ZoneInfo(name))
+    except Exception:  # noqa: BLE001 - an unknown zone must not stop delivery
+        return now
+
+
 def in_quiet_hours(now: datetime, quiet: dict) -> bool:
+    """`now` must already be in the reader's local time -- see `local_now`."""
    start = _parse_hhmm(quiet.get("start", "22:00"))
    end = _parse_hhmm(quiet.get("end", "07:00"))
    minute = now.hour * 60 + now.minute
@@ -74,7 +99,7 @@ def route(
    """
    groups = groups or {}
    quiet = delivery.get("quiet_hours", {})
-    quiet_now = in_quiet_hours(now, quiet)
+    quiet_now = in_quiet_hours(local_now(now, delivery), quiet)
    may_wake = bool(delivery.get("importance_may_wake", True))
    day_ago = now - timedelta(days=1)

@@ -83,6 +108,22 @@ def route(
    night_budget = routing.get("important_per_night", 1) - _sent_since(
        con, IMPORTANT, now - timedelta(hours=10))

+    # Minimum spacing. Budgets alone let a whole day's allowance fire in a single
+    # cycle -- six notifications landed in the same minute. A gap per lane turns
+    # the budget into a rate.
+    def _last_sent(lane: str) -> datetime | None:
+        row = con.execute(
+            "SELECT MAX(created_at) AS t FROM notification_log WHERE lane=?", (lane,)
+        ).fetchone()
+        return datetime.fromisoformat(row["t"]) if row and row["t"] else None
+
+    def _gap_ok(lane: str, minutes: int) -> bool:
+        last = _last_sent(lane)
+        return last is None or (now - last) >= timedelta(minutes=minutes)
+
+    interest_gap_ok = _gap_ok(INTEREST, routing.get("interest_min_gap_minutes", 75))
+    important_gap_ok = _gap_ok(IMPORTANT, routing.get("important_min_gap_minutes", 30))
+
    already = {
        r["cluster_id"]
        for r in con.execute(
@@ -156,6 +197,9 @@ def route(
            continue
        if s.importance_score < routing.get("important_threshold", 2.0):
            continue
+        if not important_gap_ok:
+            defer(s, "important-too-soon")
+            continue
        if important_budget <= 0:
            defer(s, "important-budget-exhausted")
            continue
@@ -168,6 +212,7 @@ def route(
                continue
            night_budget -= 1
        important_budget -= 1
+        important_gap_ok = False        # one per cycle; the rest wait for the gap
        take_group(s, "importance")
        settle(s, IMPORTANT, f"importance:{s.importance.block}", s.importance_score)

@@ -183,6 +228,9 @@ def route(
        if quiet_now:
            defer(s, "quiet-hours")
            continue
+        if not interest_gap_ok:
+            defer(s, "interest-too-soon")
+            continue
        if interest_budget <= 0:
            defer(s, "interest-budget-exhausted")
            continue
@@ -190,6 +238,7 @@ def route(
            defer(s, f"group-quota:{group_of(s, 'interest')}")
            continue
        interest_budget -= 1
+        interest_gap_ok = False         # one per cycle; the rest wait for the gap
        take_group(s, "interest")
        settle(s, INTEREST, f"interest:{s.interest.block}", s.interest_score)

@@ -88,6 +88,12 @@ important_per_day = 2
 # Hard cap on waking the reader during quiet hours, inside important_per_day.
 important_per_night = 1

+# Minimum spacing between sends on a lane. Budgets alone are not a rate: without
+# these the whole day's allowance fires in one cycle, and six notifications
+# arrived in the same minute.
+interest_min_gap_minutes = 75
+important_min_gap_minutes = 30
+
 # Thresholds are in z-score units -- "how many standard deviations above normal
 # for this block", not raw cosine. Calibrate with `news simulate`, which reports
 # the notifications-per-day these values would actually have produced.
@@ -141,4 +147,6 @@ enabled = true
 base_url = "http://litellm:4000"
 model = "news/glm-5.3-flash"
 api_key_env = "NEWS_LITELLM_KEY"
-timeout_secs = 60
+# 180, not 60: the real digest payload (28 stories) took 70.3s to generate, so a
+# 60s timeout failed every morning and silently fell back to the templated list.
+timeout_secs = 180
@@ -443,6 +443,11 @@ probes = [
 [delivery]
 digest_hour = "08:45"
 quiet_hours = { start = "22:00", end = "07:00" }
+# Read from config, NOT from the TZ environment variable. "America/Louisville"
+# resolves on the Arch host but does not exist inside a Debian container, which
+# ships only the canonical name below -- so TZ silently fell back to UTC and
+# quiet hours ran 18:00-03:00 local.
+timezone = "America/Kentucky/Louisville"
 # The importance lane MAY override quiet hours. The interest lane never may.
 importance_may_wake = true
 # No format filter: Connor reads analysis, wire copy, investigations AND opinion,
@@ -12,6 +12,12 @@ dependencies = [
    "jinja2>=3.1",
    "uvicorn>=0.30",
    "python-multipart>=0.0.9",
+    "tomlkit>=0.13",
+    # Quiet hours and the digest hour are wall-clock decisions. System zoneinfo
+    # is normally present, but this makes the zone lookup independent of the
+    # base image -- Debian ships no America/Louisville, only the canonical
+    # America/Kentucky/Louisville.
+    "tzdata>=2024.1",
    "tomlkit>=0.15.1",
 ]

@@ -154,3 +154,55 @@ def test_quiet_hours_wrap_midnight(hhmm, expected):
    h, m = map(int, hhmm.split(":"))
    now = datetime(2026, 9, 8, h, m, tzinfo=UTC)
    assert in_quiet_hours(now, {"start": "22:00", "end": "07:00"}) is expected
+
+
+# --- timezone and pacing -----------------------------------------------------
+
+DELIVERY_TZ = {**DELIVERY, "timezone": "America/Kentucky/Louisville"}
+
+
+def test_quiet_hours_use_local_time_not_utc(con):
+    """Regression for the 3:39am avalanche.
+
+    22:00-07:00 was compared against UTC hours, so notifications were silenced
+    from 18:00 local and the day's whole budget was released at 03:00 local.
+    """
+    # 23:00 UTC == 19:00 EDT: awake locally, but "quiet" if you compare UTC.
+    evening = datetime(2026, 9, 9, 23, 0, tzinfo=UTC)
+    out = route(con, [mk("a", interest=9.0)], ROUTING, DELIVERY_TZ, evening)
+    assert lanes(out)["a"] == INTEREST, "19:00 local is not quiet hours"
+
+    # 03:30 UTC == 23:30 EDT: genuinely quiet locally.
+    night = datetime(2026, 9, 10, 3, 30, tzinfo=UTC)
+    out = route(con, [mk("b", interest=9.0)], ROUTING, DELIVERY_TZ, night)
+    assert lanes(out)["b"] == DIGEST
+    assert out[0].reason == "quiet-hours"
+
+
+def test_an_unknown_timezone_does_not_stop_delivery(con):
+    delivery = {**DELIVERY, "timezone": "Mars/Olympus_Mons"}
+    out = route(con, [mk("a", interest=9.0)], ROUTING, delivery, NOW)
+    assert lanes(out)["a"] in (INTEREST, DIGEST)   # decided, not crashed
+
+
+def test_only_one_notification_per_lane_per_cycle(con):
+    """Budgets are not a rate. Six notifications once arrived in the same minute."""
+    scores = [mk(f"i{n}", interest=9.0 - n) for n in range(4)]
+    out = lanes(route(con, scores, {**ROUTING, "interest_per_day": 4},
+                      DELIVERY_TZ, NOW))
+    assert sum(1 for v in out.values() if v == INTEREST) == 1
+    assert out["i0"] == INTEREST, "the strongest candidate takes the slot"
+
+
+def test_a_second_send_waits_for_the_gap(con):
+    con.execute(
+        "INSERT INTO notification_log (cluster_id,lane,score,created_at) VALUES (?,?,?,?)",
+        ("earlier", INTEREST, 5.0, (NOW - timedelta(minutes=10)).isoformat()))
+    out = route(con, [mk("a", interest=9.0)], ROUTING, DELIVERY_TZ, NOW)
+    assert lanes(out)["a"] == DIGEST
+    assert out[0].reason == "interest-too-soon"
+
+    # Once the gap has elapsed it goes through.
+    later = NOW + timedelta(minutes=80)
+    out2 = route(con, [mk("a", interest=9.0)], ROUTING, DELIVERY_TZ, later)
+    assert lanes(out2)["a"] == INTEREST
@@ -565,6 +565,7 @@ dependencies = [
    { name = "python-multipart" },
    { name = "starlette" },
    { name = "tomlkit" },
+    { name = "tzdata" },
    { name = "uvicorn" },
 ]

@@ -584,7 +585,9 @@ requires-dist = [
    { name = "numpy", specifier = ">=1.26" },
    { name = "python-multipart", specifier = ">=0.0.9" },
    { name = "starlette", specifier = ">=0.37" },
+    { name = "tomlkit", specifier = ">=0.13" },
    { name = "tomlkit", specifier = ">=0.15.1" },
+    { name = "tzdata", specifier = ">=2024.1" },
    { name = "uvicorn", specifier = ">=0.30" },
 ]

@@ -1032,6 +1035,15 @@ wheels = [
    { url = "https://files.pythonhosted.org/packages/49/d3/b8441a820a491ddfc024b0b0cf0393375b75ea13866d9c66727e54c2fc80/typing_extensions-4.16.0-py3-none-any.whl", hash = "sha256:481caa481374e813c1b176ada14e97f1f67a4539ce9cfeb3f350d78d6370c2e8", size = 45571, upload-time = "2026-07-02T08:40:04.659Z" },
 ]

+[[package]]
+name = "tzdata"
+version = "2026.3"
+source = { registry = "https://pypi.org/simple" }
+sdist = { url = "https://files.pythonhosted.org/packages/92/ff/5a28bdfd8c3ebec42564ac7d0e54ca3db65044a9314a97f9564fa7a1e926/tzdata-2026.3.tar.gz", hash = "sha256:4a1518b8993086a7982523e071643f3c0e5f213e75b21318e78bcabfff9d1415", size = 198674, upload-time = "2026-07-10T08:50:37.887Z" }
+wheels = [
+    { url = "https://files.pythonhosted.org/packages/e5/6d/b53b99a9f2766d095985947a5782f1702cabb129a34f7a802d7197af832f/tzdata-2026.3-py2.py3-none-any.whl", hash = "sha256:dc096730c87af6cab1b171c9d532be840741ff5d459015e7f6947bd7d7e54931", size = 348168, upload-time = "2026-07-10T08:50:36.46Z" },
+]
+
 [[package]]
 name = "urllib3"
 version = "2.7.0"