From 3e61105a1daa9e76f9ddfaca989b7788e7d105c6 Mon Sep 17 00:00:00 2001 From: Broque Thomas <26755000+Nezreka@users.noreply.github.com> Date: Wed, 27 May 2026 11:33:05 -0700 Subject: [PATCH] Close three review gaps before PR 1 ships MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Self-review pass on ec4a55c1 — applying the standing kettui-grade rule (see memory/feedback_always_build_kettui_grade.md). Three issues that would have surfaced on review: 1. Silent tz fallback to UTC ``_resolve_tz`` returned UTC when the IANA name was unknown — no log, no warning. User on a host without ``tzdata`` who configures ``America/Los_Angeles`` got schedules running silently at UTC offset with no way to debug. Now logs WARNING once per unknown name (deduped via ``_UNKNOWN_TZ_WARNED`` set so a misconfigured row doesn't spam every poll cycle) and the log line names BOTH real causes — typo or missing tzdata — so the user can fix from a single grep. 2. ``weeks`` unit drift from engine I added ``'weeks': 86400*7`` to ``_INTERVAL_MULTIPLIERS`` but the engine's existing ``_calc_delay_seconds`` only recognises minutes/hours/days. Until PR 2 collapses both paths through this function, any row whose config snuck through with ``unit='weeks'`` would get scheduled by the engine as 1-hour and by this function as 7-day — drift between two live implementations. Dropped ``weeks`` from the map to match the engine. Added a comment pinning the map to the engine's contract and a regression test that asserts ``unit='weeks'`` falls back to the same hours default the engine produces. 3. DST edge cases unverified The module docstring claims DST-aware via ``zoneinfo`` but no test pinned the spring-forward gap (02:30 LA on DST-Sunday doesn't exist) or fall-back ambiguity (01:30 LA on fall-Sunday happens twice). Three new tests: - ``test_dst_spring_forward_lands_after_the_gap`` — pins that the function doesn't crash + lands on a real instant past ``now``. - ``test_dst_fall_back_handles_ambiguous_local_time`` — pins zoneinfo's default-earlier-instant resolution for ambiguous local times (01:30 PDT vs 01:30 PST → picks PDT). - ``test_weekly_across_dst_boundary_keeps_local_wall_clock`` — pins that a "every Sunday at 09:00 LA" schedule keeps the local wall clock across the boundary even though the UTC equivalent shifts by an hour. This is the exact bug class that caused the May 2026 "next in 8h" tz mismatch. Also loosened ``tzdata==2026.2`` to ``tzdata>=2024.1``. IANA tz data changes a few times a year for real-world DST policy updates; pinning to one snapshot would freeze the app's tz knowledge to the build date and miss future government-mandated rule changes. 41 schedule tests pass (5 new); 240 across the full automation suite. Ruff clean. --- core/automation/schedule.py | 38 +++++--- requirements.txt | 5 +- tests/automation/test_schedule.py | 140 +++++++++++++++++++++++++++++- 3 files changed, 170 insertions(+), 13 deletions(-) diff --git a/core/automation/schedule.py b/core/automation/schedule.py index e3b8e37b..e76636fc 100644 --- a/core/automation/schedule.py +++ b/core/automation/schedule.py @@ -58,12 +58,16 @@ from __future__ import annotations from datetime import datetime, timedelta, timezone from typing import Any, Dict, Optional +from zoneinfo import ZoneInfo, ZoneInfoNotFoundError -try: - from zoneinfo import ZoneInfo, ZoneInfoNotFoundError -except ImportError: # pragma: no cover — zoneinfo ships with 3.9+ - ZoneInfo = None - ZoneInfoNotFoundError = Exception +from utils.logging_config import get_logger + +logger = get_logger("automation.schedule") + + +# Unknown-tz names already warned about in this process — avoids +# spamming the log on every poll cycle for the same misconfigured row. +_UNKNOWN_TZ_WARNED: set = set() # Weekday abbreviation → ``datetime.weekday()`` index (Mon=0..Sun=6). @@ -74,11 +78,16 @@ _WEEKDAY_MAP = { 'mon': 0, 'tue': 1, 'wed': 2, 'thu': 3, 'fri': 4, 'sat': 5, 'sun': 6, } +# Interval multipliers — kept aligned with the engine's existing +# ``_calc_delay_seconds`` in ``core/automation_engine.py``. Adding +# entries here without also updating the engine would silently drift: +# this function would honour the new unit while the live engine path +# defaults it to hours. Keep the maps in sync until PR 2 collapses the +# engine through this function. _INTERVAL_MULTIPLIERS = { 'minutes': 60, 'hours': 60 * 60, 'days': 60 * 60 * 24, - 'weeks': 60 * 60 * 24 * 7, } @@ -256,15 +265,24 @@ def _ensure_utc(dt: datetime) -> datetime: def _resolve_tz(name: Optional[str]): - """Look up an IANA tz by name. Falls back to UTC when zoneinfo - isn't available (3.8 / minimal images) or the name is unknown.""" + """Look up an IANA tz by name. Falls back to UTC when the name is + unknown — ``ZoneInfoNotFoundError`` is the symptom of either a + typo in the tz string or ``tzdata`` missing on the host. Logged + once per unknown name so the user can see WHY their schedule + isn't running in the timezone they configured.""" if not name: return timezone.utc - if ZoneInfo is None: - return timezone.utc try: return ZoneInfo(name) except ZoneInfoNotFoundError: + if name not in _UNKNOWN_TZ_WARNED: + _UNKNOWN_TZ_WARNED.add(name) + logger.warning( + "Unknown timezone %r — schedule will run against UTC. " + "Check the spelling (IANA format like 'America/Los_Angeles') " + "or install the `tzdata` package on minimal hosts.", + name, + ) return timezone.utc diff --git a/requirements.txt b/requirements.txt index 4a94d257..b1fda9f0 100644 --- a/requirements.txt +++ b/requirements.txt @@ -32,7 +32,10 @@ psutil==7.2.2 # minimal Docker base images that ship without the system tz database. # Consumed by ``core/automation/schedule.py`` for daily / weekly / # monthly schedule next-run computation in the user's local timezone. -tzdata==2026.2 +# Loose-pinned because IANA tz data changes a few times a year for +# real-world DST policy updates; pinning to one snapshot would freeze +# the app's tz knowledge to the build date. +tzdata>=2024.1 # YouTube support -- unpinned; yt-dlp must track upstream releases to stay functional yt-dlp>=2026.3.17 diff --git a/tests/automation/test_schedule.py b/tests/automation/test_schedule.py index a73782ff..e7301a0f 100644 --- a/tests/automation/test_schedule.py +++ b/tests/automation/test_schedule.py @@ -61,15 +61,27 @@ def test_returns_none_for_non_dict_config(): ('minutes', 60), ('hours', 3600), ('days', 86400), - ('weeks', 86400 * 7), ]) def test_interval_units(unit, seconds_per_unit): - """Every supported unit scales the interval correctly.""" + """Every supported unit scales the interval correctly. Kept in + lockstep with the engine's existing ``_calc_delay_seconds`` map + — see _INTERVAL_MULTIPLIERS docstring.""" now = _utc(2026, 5, 27, 12, 0) result = next_run_at('schedule', {'interval': 3, 'unit': unit}, now) assert result == now + timedelta(seconds=3 * seconds_per_unit) +def test_interval_weeks_unit_falls_back_to_hours_matching_engine(): + """Engine's ``_calc_delay_seconds`` only recognises minutes / hours + / days — anything else defaults to hours. Drift between this helper + and the engine would silently mis-schedule rows whose config snuck + through with an unsupported unit. Pin the alignment until PR 2 + collapses both paths through this function.""" + now = _utc(2026, 5, 27, 12, 0) + # 'weeks' is not in our map; falls back to hours. + assert next_run_at('schedule', {'interval': 2, 'unit': 'weeks'}, now) == now + timedelta(hours=2) + + def test_interval_unknown_unit_defaults_to_hours(): """Backward compat with DB rows whose ``unit`` field is missing or an unrecognised value — engine's historic behaviour was to @@ -180,6 +192,130 @@ def test_daily_unknown_tz_falls_back_to_utc(): assert result == _utc(2026, 5, 27, 15, 0) +def test_unknown_tz_logs_warning_once(caplog): + """Silent fallback to UTC was a bug — user configures + 'America/Los_Angeles' but tzdata is missing → schedule runs at the + wrong hour with no log line. Log once per unknown name so the + misconfiguration is debuggable from a single grep, and don't spam + the log on every poll cycle for the same row.""" + import logging + from core.automation import schedule + schedule._UNKNOWN_TZ_WARNED.clear() # fresh state for the test + now = _utc(2026, 5, 27, 12, 0) + with caplog.at_level(logging.WARNING, logger='soulsync.automation.schedule'): + # Two calls with the same bad name — only ONE warning emitted. + next_run_at('daily_time', {'time': '09:00', 'tz': 'Bogus/Tz'}, now) + next_run_at('daily_time', {'time': '09:00', 'tz': 'Bogus/Tz'}, now) + matching = [r for r in caplog.records if 'Bogus/Tz' in r.getMessage()] + assert len(matching) == 1 + assert 'tzdata' in matching[0].getMessage().lower() + + +def test_unknown_tz_warning_includes_helpful_hint(): + """Log line must point the user at the two real causes: typo in + the IANA name, or missing tzdata on the host. Without that hint + the symptom (schedule running at UTC offset) is bewildering.""" + import logging + from core.automation import schedule + schedule._UNKNOWN_TZ_WARNED.clear() + caplog_records = [] + + class _Capture(logging.Handler): + def emit(self, record): + caplog_records.append(record.getMessage()) + + handler = _Capture() + logger_obj = logging.getLogger('soulsync.automation.schedule') + logger_obj.addHandler(handler) + try: + next_run_at('daily_time', {'time': '09:00', 'tz': 'Made/Up'}, + _utc(2026, 5, 27, 12, 0)) + finally: + logger_obj.removeHandler(handler) + assert any("'Made/Up'" in m for m in caplog_records) + assert any('IANA' in m for m in caplog_records) + + +# --------------------------------------------------------------------------- +# DST edge cases — pin that ``zoneinfo``'s default resolution handles +# spring-forward gap + fall-back ambiguity sensibly. Both transitions +# happen in the user's local tz, NOT in UTC, so the result UTC offset +# changes across the boundary. +# --------------------------------------------------------------------------- + + +def test_dst_spring_forward_lands_after_the_gap(): + """In Los Angeles, 2026-03-08 02:30 doesn't exist — clocks jump + from 02:00 PST directly to 03:00 PDT. A schedule for 02:30 daily + that fires through this transition must NOT raise and must land + on a real instant. ``zoneinfo``'s default resolution maps the + gap to the post-jump side (treating 02:30 as 03:30 PDT), so the + UTC equivalent shifts by an hour relative to non-DST days.""" + # 2026-03-08 00:00 UTC = 2026-03-07 16:00 PST (still PST). + # Schedule fires 02:30 LA daily. Next run on 03-07 was 02:30 PST + # = 10:30 UTC. We're querying after that → next run is 03-08 + # 02:30 LA, which falls in the spring-forward gap. zoneinfo + # resolves to 03:30 PDT = 10:30 UTC (offset already shifted to + # PDT for the rest of the day post-transition). + now = _utc(2026, 3, 8, 0, 0) + result = next_run_at('daily_time', + {'time': '02:30', 'tz': 'America/Los_Angeles'}, + now) + # Must be aware UTC, must NOT crash on the gap. + assert result is not None + assert result.tzinfo is not None + # Result is somewhere on 03-08 — exact time depends on zoneinfo's + # gap-resolution policy, but it must be on the right day and + # past ``now``. + assert result > now + assert result.date() == datetime(2026, 3, 8).date() + + +def test_dst_fall_back_handles_ambiguous_local_time(): + """2026-11-01 01:30 in Los Angeles happens TWICE (once at PDT + UTC-7, once at PST UTC-8 after the fall-back). A daily schedule + for 01:30 must resolve to ONE instant — ``zoneinfo``'s default + picks the first occurrence (PDT), so the UTC time is 08:30.""" + # 2026-11-01 00:00 UTC = 2026-10-31 17:00 PDT. + # Next 01:30 LA is 2026-11-01 — ambiguous, zoneinfo defaults to + # the earlier (PDT) instant: 08:30 UTC. + now = _utc(2026, 11, 1, 0, 0) + result = next_run_at('daily_time', + {'time': '01:30', 'tz': 'America/Los_Angeles'}, + now) + assert result is not None + # 01:30 PDT (UTC-7) → 08:30 UTC. + assert result == _utc(2026, 11, 1, 8, 30) + + +def test_weekly_across_dst_boundary_keeps_local_wall_clock(): + """User schedules "every Sunday at 09:00 LA". Crossing the + spring-forward DST boundary, the LOCAL wall clock stays at 09:00 + even though the UTC equivalent shifts by an hour. Pre-DST Sunday + 09:00 PST = 17:00 UTC; post-DST Sunday 09:00 PDT = 16:00 UTC.""" + # Pre-DST Sunday: 2026-03-01. + pre_dst = _utc(2026, 3, 1, 10, 0) # Sunday 02:00 PST already past 09:00? No — 02:00 < 09:00, so today still qualifies. + result_pre = next_run_at('weekly_time', + {'time': '09:00', 'days': ['sun'], + 'tz': 'America/Los_Angeles'}, + pre_dst) + # 09:00 PST = 17:00 UTC. + assert result_pre == _utc(2026, 3, 1, 17, 0) + + # Post-DST Sunday: 2026-03-15 (the 8th was DST switch day). + post_dst = _utc(2026, 3, 15, 10, 0) # 03:00 PDT — before 09:00. + result_post = next_run_at('weekly_time', + {'time': '09:00', 'days': ['sun'], + 'tz': 'America/Los_Angeles'}, + post_dst) + # 09:00 PDT = 16:00 UTC. + assert result_post == _utc(2026, 3, 15, 16, 0) + # Same local wall clock, different UTC — the kind of bug that + # caused the May 2026 "next in 8h" tz mismatch. + assert result_pre.hour == 17 + assert result_post.hour == 16 + + # --------------------------------------------------------------------------- # Weekly (``trigger_type='weekly_time'``) # ---------------------------------------------------------------------------