delay.run

Posted on Nov 6 Edited on Nov 6

Postmortem: the nightly sync ran green for 23 days while syncing nothing

#postmortem #backend #api #cron

This is a composite postmortem. The pattern is real and common; the details are illustrative.

Summary

A nightly job synced customer orders from a partner's API into our database. For 23 days, it ran on schedule, exited with code 0, and logged "sync complete". It synced zero orders. The partner's API token had expired, and our code turned "unauthorised" into "no new orders".

We found out when a customer asked why their dashboard hadn't changed in three weeks.

The job

# sync_orders.py — runs nightly at 02:30
def fetch_new_orders(since):
    resp = requests.get(
        f"{PARTNER_API}/orders",
        params={"since": since.isoformat()},
        headers={"Authorization": f"Bearer {TOKEN}"},
        timeout=30,
    )
    data = resp.json()
    return data.get("orders", [])

def main():
    since = last_sync_time()
    orders = fetch_new_orders(since)
    for o in orders:
        upsert_order(o)
    set_last_sync_time(now())
    log.info("sync complete: %d orders", len(orders))

Read it carefully and you'll spot three problems.

What happened

The partner issued API tokens valid for one year. Ours was created by an engineer who'd since moved teams. Nobody had the expiry date written down.
On day 0, the token expired. The partner's API started returning 401 Unauthorized with a JSON body like {"error": "token_expired"}.
Our code never checked the status code. resp.json() parsed the error body fine. data.get("orders", []) returned an empty list.
Zero orders were processed. The log said sync complete: 0 orders.
Then the worst line ran: set_last_sync_time(now()). Every night, the "since" cursor moved forward, as if we'd successfully synced everything up to that moment.
Our job monitoring checked that the job ran and exited 0. It did both, every night.

Detection

Day 23: a customer emailed support. Their order dashboard had been unchanged for three weeks. Support escalated; an engineer ran the job by hand with debug logging and saw the 401 immediately.

Impact

23 days of partner orders missing for all customers using that integration.
Because the cursor had advanced, simply fixing the token wasn't enough. The next run would only fetch orders from that day onward.

Recovery

A new token was issued and stored.
The cursor was manually reset to the last known good sync (found from the last non-zero log line).
The backfill was run in daily chunks to respect the partner's rate limits.
Customers on the integration were told what happened and when data would be complete.

Root causes

HTTP errors weren't treated as errors. The code assumed any JSON response was a success.
"Nothing to do" and "couldn't check" looked identical. An empty list was a valid answer, and an error produced an empty list.
The cursor advanced on failure. The job recorded progress it hadn't made.
Monitoring checked the wrong thing. "Did it run?" isn't "did it work?"
Credentials had no owner or expiry tracking.

Fixes

Fail loudly on HTTP errors

def fetch_new_orders(since):
    resp = requests.get(
        f"{PARTNER_API}/orders",
        params={"since": since.isoformat()},
        headers={"Authorization": f"Bearer {TOKEN}"},
        timeout=30,
    )
    resp.raise_for_status()               # 401, 403, 429, 5xx → exception
    data = resp.json()
    if "orders" not in data:
        raise ValueError(f"unexpected response shape: {list(data)[:5]}")
    return data["orders"]

Only advance the cursor to what you actually processed

def main():
    since = last_sync_time()
    run_started = now()
    orders = fetch_new_orders(since)      # raises on failure; cursor untouched
    for o in orders:
        upsert_order(o)
    # Advance to the time we *queried at*, not "now" after processing
    set_last_sync_time(run_started)
    log.info("sync ok since=%s orders=%d", since.isoformat(), len(orders))

Alert on suspicious success

Zero results isn't always wrong, but zero results for several nights in a row, from a partner that normally sends hundreds, is almost certainly a problem:

recent = recent_run_counts(days=3)        # e.g. [0, 0, 0]
typical = median(recent_run_counts(days=30))
if typical > 20 and all(c == 0 for c in recent):
    alert(f"orders sync: 0 orders for 3 nights (typical {typical}). Check credentials and API.")

Track credentials like they're infrastructure

Every API token used by scheduled jobs now has an entry in a simple inventory: what it's for, who owns it, when it expires. A scheduled reminder fires 30 days and 7 days before each expiry. Whether you schedule those reminders with your own cron, a calendar, or a hosted scheduler like delay.run matters less than having them at all.

Where the API offers it, we also call a cheap authenticated endpoint at the start of each run (a "who am I" or similar), so credential problems fail fast with a clear message.

Add a test for the failure path

The original code had tests, but only for the happy path. We added one for the case that actually happened:

def test_sync_does_not_advance_cursor_on_401(monkeypatch, fake_api):
    fake_api.respond(status=401, json={"error": "token_expired"})
    before = last_sync_time()
    with pytest.raises(requests.HTTPError):
        main()
    assert last_sync_time() == before

It's a five-minute test that would have turned 23 silent days into one failed night.

What went well

The raw data still existed on the partner's side, so the backfill was complete.
Once someone looked, diagnosis took minutes.

Lessons

Exit code 0 is not a success metric. Measure what the job was supposed to produce.
Never let an error masquerade as "no data".
Don't advance a cursor past work you didn't do.
Every credential a scheduled job uses will expire or be revoked one day. Plan for that day.

DEV Community