🐛 Something is causing my team's cron tasks to occasionally get delayed and reported as "missed" in Sentry

[coredumperror]

Bug Description

As I mentioned in #44, my team is occasionally getting "missed" cron reports from Sentry. I've now figured out what seems to be the reason behind our tasks being marked as "missed", though I'm really not sure what could be causing it. I've attached a json blob with our logs from a short period this morning when our every-five-minutes cron task starting throwing "Cron failure" messages on Sentry for a few minutes.

logs-insights-results.json

At 10:00am PST (17:00 UTC in the logs), the task went fine.

At 17:05:00 the scheduler claimed to have started the job, but the RQ worker didn't actually start running the task until 17:07:37, after which it quickly finished (Sentry called this a "Cron failure" and emailed us).

At 17:10 the scheduler claimed it started the job, but the worker never did anything at all.

At 17:15, the scheduler claimed to have started the job, but the worker didn't start running it until 17:17:40.

Then at 17:20, something especially interesting happened. The job "started" on time, but didn't run until 17:21:45, when two instances of the job ran simultaneously (note that there are two publish_scheduled_pages.start logs within that second). Perhaps the second one is the missed job from back at 17:10?

Finally, at 17:25 the job ran completely normally, and it has run successfully every 5 minutes for the several hours since then.

Speaking with my colleagues about this, it seems like we've been getting problems similar to this ever since we switched two of our apps from using Celery for scheduled tasks, to using the Django Tasks framework with django-crontask for the scheduling. The problem is thankfully fairly rare, and it doesn't seem to last long, but it's quite concerning. Any help you can provide would be greatly appreciated.

Expected Behavior

I expect cron tasks to run when they're scheduled to run, rather than sometimes running a few minutes later.

Version

1.2.0

Stack trace

No response

Steps to Reproduce

No response

[codingjoe]

Hi @coredumperror,

Thank you for sharing some logs. Based on your information and my personal experience, this is likely an orchestration issue.

You probably have too long queues (queue congestion): The scheduler schedules a task by adding it to the message queue via Django's API Task.enqueue. The scheduler does NOT actually process any tasks. Your workers do. However, if you have only a single queue, a task might be waiting in line for some time. If you have time-critical tasks, either use a priority queue or create a different queue and worker pool to process those tasks. If Sentry shows delayed tasks, this is most certainly the reason. And Sentry is correctly warning you about an orchestration issue.

My advice: move all cron tasks to a separate queue and worker pool. Or at least don't aim for low workload volatility.

Let me know if you have more questions or information I can use to further narrow down the issue.

Cheers!
Joe

[coredumperror]

All this task queue stuff is new to me, so I'm not entirely sure how to do what you're suggesting. I'll look into it.

I imagine that maybe Wagtail (the CMS framework our site is built on) is putting its async tasks (like updating the search index when a page is saved) on the same queue as our cron tasks, but I really don't see how that could delay our cron tasks by several minutes. Wagtail's async tasks should take only fractions of a second to run, and we don't have all that many active users editing pages at once, especially not on our main website.

[codingjoe]

You are using celery, right? You can use Celery Flower to monitor tasks more closely. Your logs should also be a pretty good place for further investigation. You can check if there are certain tasks to skip. There are multiple reasons why task processing can be clogged, and it's hard for me to judge without much more information. If you don't want to share more debugging data openly, you can either send it to me via email or ask your favorite AI agent. They are usually pretty good at bug hunting.

As for this package, again, it only adds tasks to the queue. What happens to them afterwards isn't handled here. The easiest way to avoid congestion, is to provide a different queue for time sensitive tasks, or even a different backend. (Note that a synchronous backend will pause the scheduler).

[coredumperror]

We used Celery before switching it out for Django Tasks + crontask, and thus no longer use Celery (in this app). We had been using it exclusively for cron jobs like this one, which had always felt like overkill for a system as powerful as Celery. That's why we wanted to try a lighter weight alternative, now that Django offers outside-the-request-cycle functionality of its own.

As for my experiments with separate task queues, I managed to put the cron tasks on a special "cron" queue that I defined in RQ_QUEUES, and I think that may have helped. I'm not seeing any delayed task executions in the logs over the 18 hours since I deployed that change, so... fingers crossed!

However, I am now seeing what appears to be a brand new problem with the cron monitoring. Or maybe it's still the original source of the monitor failures, and the delayed logs were just a red herring? Anyway, what's happening is that of the four ECS instances that our main app's server runs on, the majority of the time, at least one of them reports a cron task timeout. (Recall the change I made regarding "make the scheduler run on every instance, and use a task-level lock in redis so that only one instance actually performs the task", which is why we get 4 checkins).

Here's what that looks like in Sentry:

The CloudWatch logs show that every actual task run is starting and finishing successfully, and it seems like the other three instances are correctly reporting "I couldn't acquire the lock, so I'm skipping the task". Which leaves me scratching my head as to what could be causing these apparently spurious failed monitor reports. And just to add insult to injury, these failed reports never happen in test. Sentry's cron monitor timeline is 100% green across the board on those servers.

The next thing I'm going to try is doing the cron monitoring entirely within our own code, rather than using crontask's implementation. That'll let me avoid the extra checkins for the "I didn't actually do the task" instances, and also give me a bit more configurability, and possibly more insight into the monitoring itself.

[coredumperror]

Huh... Correct me if I'm wrong, but is it possible to tell crontask to not monitor your cron jobs with Sentry if you have the sentry_sdk installed? It looks like crontask.contrib.sentry.monitor_cron_task() automatically adds a monitor if sentry_sdk is merely installed, regardless of whether you installed django-crontask with the [sentry] optional dependency.

I want to disable crontask's monitoring so I can roll my own, but that doesn't seem to be possible.

[jayblast-spec]

The queue congestion fix was right, but the Sentry false positives you're seeing now are the same root cause showing up in a different place, not a new bug.

Sentry's cron monitor treats your check-in schedule as a promise about when work happens. Your scheduler enqueues on schedule, but a worker actually picks it up whenever the queue gets to it. Under load, that gap grows. If your monitor's check-in margin (or max_runtime, depending on how you've wired the @monitor decorator or sentry_sdk.crons.capture_checkin) is set to expect execution close to the scheduled time, Sentry will flag anything that clears that margin as missed or timed out, even though CloudWatch shows it finished fine.

Two ways to fix it properly, not just silence it:

1. Widen the monitor's checkin_margin and max_runtime to reflect your queue's real worst-case dispatch latency under load, not your best-case local testing time. If a job can legitimately sit in queue for 3 minutes when things are busy, your margin has to tolerate that or you'll always get noise during congestion.

2. Better: move the "in progress" check-in to fire when the worker actually starts processing, not when the scheduler enqueues. Right now Sentry is monitoring your scheduler's punctuality, not your job's health. Those are different things, and the second one is what you actually care about. If a job sits in queue for a while but then runs and succeeds, that's a queue capacity problem worth knowing about separately, not a task failure.

On disabling automatic monitoring to roll your own: you can, but before you do, consider whether what you actually want is just decoupling the check-in trigger from enqueue-time, per point 2 above. That usually gets you accurate signal without losing Sentry's dashboard and alerting for free.