Skip to content

Suite 36: beat last_run_at persistence root cause + ingestion funnel dead-ends (36.1–36.4) - #37

Merged
aryavenkatesan merged 5 commits into
mainfrom
fix/suite-36-beat-persistence
Jul 30, 2026
Merged

Suite 36: beat last_run_at persistence root cause + ingestion funnel dead-ends (36.1–36.4)#37
aryavenkatesan merged 5 commits into
mainfrom
fix/suite-36-beat-persistence

Conversation

@aryavenkatesan

Copy link
Copy Markdown
Collaborator

Builds suite 36. 36.5 is deliberately not implemented — see below.

The headline: 36.4's root cause

healthcheck.service was failing hourly on prod with broadcast-orphan-recovery STALE. The previous session read that as a too-tight window and drafted 36.5 to widen it 7h → 13h. That was wrong.

django-celery-beat holds PeriodicTask.last_run_at in memory and writes it only when Scheduler._do_sync() runs. Both triggers were defeated:

  • CELERY_BEAT_MAX_LOOP_INTERVAL = 6h becomes Scheduler.max_interval (celery/beat.py:253-256), overriding django-celery-beat's DEFAULT_MAX_INTERVAL = 5s. Service.start() (beat.py:645-652) calls _do_sync() only after time.sleep(interval), so beat can sleep 6h between sync opportunities.
  • apply_async's finally (beat.py:416-418) is gated on should_sync(), whose task-count clause is dead because beat_sync_every defaults to 0.

Measured on prod, not inferred:

22:24:33  BEFORE   last_run_at = 12:00:01.808480   runs =  9
22:24:35  systemctl restart celerybeat
22:24:37  AFTER    last_run_at = 18:00:00.021322   runs = 10

The 18:00 write sat in memory for 4h24m and flushed only on shutdown. The task was sent (18:00:00,023) and executed (worker: succeeded in 0.083s) on time — only the bookkeeping was late. Fix: CELERY_BEAT_SYNC_EVERY = 1, which flushes after every send without touching the loop interval (that 6h value exists to reduce Neon serverless wake-ups).

Hypotheses disproven along the way, recorded so nobody re-chases them: dev/prod DB split; the swallowed ObjectDoesNotExist at schedulers.py:459; a stale in-memory _schedule; and clock skew — beat's startup banner is flushed at teardown and reports that process's own start time, which looks exactly like an 18-minute clock drift in journalctl and is not.

Why 36.5 is closed won't-fix

A 13h window would have reported OK at 9.7h stale, silencing a real bug. It also wouldn't have worked: with sync starved, age grows without bound, so 13h FAILs at 01:00 UTC anyway.

Then it happened a second time. Tightening 36.3's grace from 7h to 5min exposed a permanent 4–5h timezone error, every day, for all three America/New_York crontab tasks. TzAwareCrontab converts last_run_at into the schedule's tz inside is_due() (tzcrontab.py:39) but inherits remaining_estimate/remaining_delta unmodified from celery, which read .hour/.minute/.isoweekday() off whatever tzinfo the datetime carries (celery/schedules.py:577-605). The old 7h grace had been absorbing it silently. Fixed in the computation via .astimezone(schedule.tz), not by widening grace back out. Reproduces mid-June, so it was never a DST-only bug.

If a monitoring threshold needs widening to go green, suspect the measurement.

Contents

Ticket Change
36.1 skipped_no_town terminal status; added to CANDIDATE_STATUSES; reopen_skipped_towns command; migration backfills 27 prod rows (Apex 15, Durham 12)
36.2 Backfills 14 of 15 town-less events; Jordan Lake left NULL on purpose
36.3 Crontab-derived expected-fire checks replace hand-tuned windows; grace keyed to SYNC_EVERY; tz fix above
36.4 CELERY_BEAT_SYNC_EVERY = 1 + regression test + incident writeup
36.5 Closed won't-fix

Detection latency for a missed weekly digest: ~8 days → ~5 min.

36.1 bundles the devtools funnel fix deliberately — the new status fell into no funnel bucket, silently breaking the documented "buckets sum to raw" invariant and dropping 27 rows out of the monitor. Splitting them would plant a commit with failing tests. That invariant was a comment; it is now a test, hardened to fail on any future unwired bucket.

Verification

549 backend tests OK · ruff check clean · ruff format --check clean · mypy no issues · no migration drift. Run serially — this repo shares one Neon test DB and concurrent runs produce meaningless results.

Reviewer attention, please

  • Covenant Place → carrboro (36.2, 11 of the 15 rows). Product decision: it's Carrboro Parks & Rec programming, though the building's postal address is Chapel Hill. Centralised in VENUE_TOWN_MAP, one line to change.
  • Coverage fixes are no longer free. 35.14's trick — add a Town, stranded rows republish themselves — stops working. Adding coverage now needs manage.py reopen_skipped_towns.
  • Two prod data migrations here: ingestion/0016 (27 staged rows) and events/0017 (14 live events). Both reversible.
  • weekly-digest-sunday will still FAIL after deploy, until it sends on 2026-08-02. That is correct signal — beat was dead through Sunday 2026-07-26 so that week's digest genuinely never went out. Do not "fix" it.

Not done

Prod verification after deploy: confirm healthcheck.service reports broadcast-orphan-recovery OK.

🤖 Generated with Claude Code

aryavenkatesan and others added 5 commits July 30, 2026 01:21
A staged event whose town had no `Town` row stayed `approved` forever and
re-logged a warning on every pipeline run — 27 rows on prod (Apex 15,
Durham 12) burning 27 unactionable log lines per run. That is how Siler
City's dropped events went unnoticed for weeks (35.14).

Adds `skipped_no_town`, set at the skip point, so the row leaves the
`approved` queryset and the warning fires exactly once. Added to
`deduplicator.CANDIDATE_STATUSES` so a re-scrape collapses onto the
existing row instead of inserting a fresh one each poll. Coverage fixes
are no longer free: `manage.py reopen_skipped_towns` re-opens rows once a
`Town` lands. Migration backfills the 27 existing rows.

Includes the devtools funnel fix in the same commit deliberately — the
new status fell into no funnel bucket, silently breaking the documented
"buckets sum to raw" invariant and dropping 27 rows out of the monitor.
Splitting these would plant a commit with failing devtools tests. The
monitor now surfaces a `no_town` bucket with an explanatory note, which
is what 36.1 wanted: `raw > 0, published = 0` now says why. The
reconcile test sums buckets dynamically so a future unwired bucket fails
instead of passing silently.

Co-Authored-By: Claude <noreply@anthropic.com>
All 15 had an empty `source_name`, so they predate the ingestion pipeline
— hand-entered rows whose town was never resolved. 11 of 15 are one
recurring "Senior ..." series at Covenant Place.

Mapping: Fair Game Beverage Company, bmc brewing and Chatham YMCA ->
pittsboro; Covenant Place -> carrboro (Carrboro Parks & Rec programming,
per product decision, though the building's postal address is Chapel
Hill). The Jordan Lake spring-cleanup row is left NULL on purpose: the
recreation area spans Wake and Chatham with access points in different
towns, and a wrong town puts an event on the wrong hub page.

`Event.town` stays nullable — ingestion legitimately produces unmatched
towns (36.1).

Co-Authored-By: Claude <noreply@anthropic.com>
Root cause of the hourly `healthcheck.service` failure. django-celery-beat
holds `PeriodicTask.last_run_at` in memory and writes it only when
`Scheduler._do_sync()` runs. Both sync triggers were defeated:

- `CELERY_BEAT_MAX_LOOP_INTERVAL = 6h` becomes `Scheduler.max_interval`
  (celery/beat.py:253-256), overriding django-celery-beat's
  DEFAULT_MAX_INTERVAL of 5s. `Service.start()` (beat.py:645-652) calls
  `_do_sync()` only after `time.sleep(interval)`, so beat can sleep 6h
  between sync opportunities.
- `apply_async`'s finally (beat.py:416-418) is gated on `should_sync()`,
  whose task-count clause is dead because `beat_sync_every` defaults to 0.
  A task firing shortly after a prior sync flushes nothing.

Measured on prod: a write made at 18:00:00 was still absent 4h24m later
and appeared the instant celerybeat was restarted (shutdown's
`finally: self.sync()` flushed it) — 12:00:01/runs=9 -> 18:00:00.021/runs=10.
The task was sent AND executed on time; only the bookkeeping was late.

Fix is `CELERY_BEAT_SYNC_EVERY = 1`, forcing a flush after every send.
Costs one UPDATE per fire and deliberately does not touch the loop
interval, which exists to reduce Neon serverless wake-ups.

Note this means PR #36's 7h staleness window was not "too tight" — it was
comparing against a column that lagged by up to 6h. Widening it to 13h
(the original 36.5) would have turned a true positive into a pass and
buried this bug.

Co-Authored-By: Claude <noreply@anthropic.com>
A staleness window must exceed the task's period, so every task had a
blind spot at least one period wide — a missed weekly digest rode along
for ~8 days. Now `_task_freshness` asks the schedule itself:

    expected_next = now + schedule.remaining_estimate(last_run_at)

`DEFAULT_STALENESS_HOURS` is demoted to (a) the must-exist task set, which
still catches a seeded task vanishing from the schedule (2026-07-21
outage), and (b) a fallback window for interval-backed tasks only.

Grace is keyed to `CELERY_BEAT_SYNC_EVERY`: 5 minutes when it is set (the
persistence lag is gone — see 36.4), automatically re-widening to
MAX_LOOP_INTERVAL + 1h if it is ever removed. Evaluated at call time so
`@override_settings` can reach both branches.

Also fixes a bug the tightened grace exposed. `TzAwareCrontab` converts
`last_run_at` into the schedule's tz inside `is_due()` (tzcrontab.py:39)
but inherits `remaining_estimate`/`remaining_delta` unmodified from
celery, which read `.hour`/`.minute`/`.isoweekday()` off whatever tzinfo
the datetime carries (celery/schedules.py:577-605). Calling
`remaining_estimate()` with UTC datetimes therefore compared
America/New_York crontab fields against UTC clock fields — a permanent
4-5h error every day for ingest-events-daily, scrape-sources-daily and
weekly-digest-sunday. Not a DST-only bug; it reproduces mid-June. The old
7h grace had been silently absorbing it. Fixed by converting both
operands via `.astimezone(schedule.tz)`, mirroring `is_due()`, rather than
widening grace back out.

Detection latency: ~8 days -> ~5 min for a missed weekly digest.

Co-Authored-By: Claude <noreply@anthropic.com>
36.1–36.4 built and green. 36.5 recorded as won't-fix: widening the
orphan-recovery staleness window to 13h would have converted a true
positive into a pass and buried 36.4's root cause.

OUTBOX.md carries the full change blocks (gitignored, so it does not
travel with this commit). Note the board still shows every suite back to
17 as _(pending)_ — the desktop app has never synced.

Co-Authored-By: Claude <noreply@anthropic.com>
@aryavenkatesan
aryavenkatesan merged commit 590781b into main Jul 30, 2026
5 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant