The Cron That Ran for Weeks and Did Nothing

A runner in red shoes mid-jump against a blue sky, photographed from below with a fisheye lens so the ground curves beneath themPhoto: Venti Views
On this page

For weeks, the log of PayGlue’s nightly maintenance job looked like this:

== enforce_downgrade_grace_periods
No accounts past their downgrade grace period.

One line of output and a clean exit, the same every single night. The scheduler showed a green run, and I looked at that green run more than once and moved on.

The job was supposed to do seven things.

Before the story, one fact that matters: these are PayGlue’s own housekeeping jobs. The path a customer’s purchase takes, webhook in, Ghost member out, is a separate process that never touched this scheduler. Every reader who paid got their access throughout. The only party not being looked after was us.

What was supposed to happen

The nightly run on the hosted service is a chain of maintenance tasks. It enforces downgrade grace periods and expires tester access. It polls our own subscriptions at the payment provider and sends the lifecycle emails that come out of that. It pauses accounts whose grace period ran out, purges webhook payloads past their retention date, sends delivery alerts for Ghost connections that keep failing, and syncs support ticket statuses.

Seven tasks, one start command, chained with &&:

python manage.py enforce_downgrade_grace_periods && python manage.py expire_tester_access && ...

That is a perfectly normal thing to write. I have written it a hundred times. It also means that if any link exits with a non-zero code, the rest never run, and the shell reports whatever the last link reported.

What actually happened

Only the first link ran, every night, for weeks.

I found it sideways. While checking something else, a dry run of the subscription poll listed seven onboarding emails that should have gone out days earlier. That made no sense if the poll had been running. So I read the cron logs properly for the first time, and every night had exactly one line in it.

Then I ran the other six tasks by hand. The payload purge found 118 raw webhook payloads that should have been cleaned up a week after processing. The support sync moved a ticket from open to done that had been done for days. The subscription poll had never once looked at a customer.

The part I still cannot explain

I do not know why the chain stopped after the first link. The first task exited cleanly by every measure I could find. I rebuilt the situation, read the platform’s documentation on start commands, and did not find the cause.

I spent an afternoon on it and then stopped, because the fix did not depend on the answer. Whatever broke the chain, the chain itself was the design flaw: a sequence where one failure quietly ends everything and the scheduler cannot tell.

What replaced it

One command now runs the whole night:

python manage.py run_nightly_jobs

It runs each task itself, in order, in one process. Each task is isolated, so if one raises, the traceback goes to the log and the next task still runs. At the end the command exits non-zero if anything failed. The scheduler shows a red run for a night that had a problem, and a green run only for a night where everything ran.

It does two other things. It prints a header line for every task, so the log for a good night is seven headers and their output, and a night with one line in it cannot be mistaken for a good one. And if a task is not installed, which happens in the open source build where some hosted-only jobs do not ship, it says so and moves on.

Why 800 tests did not help

Every one of the seven tasks had tests, and the tests passed. They still pass today.

Tests exercise the task. They do not exercise the start command in a deployment configuration on a hosting platform. That line was code too. It had no test and no review, and I never properly read what it produced.

The pattern is the same one I ran into when I followed my own setup guide and it broke the install. The code was fine both times. What was wrong was the thing around the code, and nothing was checking that.

What I do differently now

Once a week I open the logs and look for the seven headers instead of the green tick. And every task that sends something or deletes something now writes a line saying what it did, including “nothing to do”, so an empty log means the task did not run rather than that it had nothing to say.

There is a second habit, and it is the cheaper one. For every scheduled job, I now know one side effect I can check from the outside. For the subscription poll that is an email that should be sitting in a mailbox. For the purge it is a row count that should have dropped, and for the support sync a ticket status that should have moved. If the side effect is missing, the job did not run, whatever the scheduler says. That check takes a minute and would have caught this in the first week instead of the sixth.

The subscription poll, by the way, found its first real case the second night it ran. I am glad it was the second night and not the twentieth.

Photo by Venti Views on Unsplash

Frequently asked

How do you notice a scheduled job that runs but does nothing?

Not from the scheduler. It reports that the process started and exited. You notice from the side effects that are missing: emails that should have gone out, rows that should have been cleaned up. Check the outcome, not the run.

What is wrong with chaining commands with && in a start command?

It stops at the first non-zero exit, silently, and the scheduler still sees a completed run. One process that runs each task itself, logs failures with a traceback and returns a non-zero exit at the end tells you the truth.

Why did the tests not catch this?

Every task had tests, and every task worked. The failure was in how they were started, which no unit test exercises. Deployment configuration is code too, and it had none.