Kuma: T - Edits are not being applied

[wbamberg]

https://wiki.developer.mozilla.org/en-US/docs/Web/API/Window/sidebar is not showing any of the edits I've made in the last day: https://wiki.developer.mozilla.org/en-US/docs/Web/API/Window/sidebar$compare?locale=en-US&to=1629260&from=1609228.

[wbamberg]

Also: https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-block

https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-block$compare?locale=en-US&to=1629267&from=1629196

[escattone]

cc @tobinmori and @atopal (and also @limed in case he has any insights that can help with this)

This is also happening with https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-wrap and https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-x.

For all of the cases https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-block, https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-wrap, and https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-x, I've confirmed that the render was marked as scheduled (see example below) but the Celery task was never received by any workers because the Celery-worker logs show no message like Received task: kuma.wiki.tasks.render_document[...] at the expected time. Certainly the render was never attempted, because the render_started_at time is for an earlier render that was successfully completed.

>>> doc = Document.objects.get(slug="Web/CSS/overflow-block", locale="en-US")
>>> doc.render_scheduled_at
datetime.datetime(2020, 6, 18, 16, 28, 59, 60477)
>>> doc.render_started_at
datetime.datetime(2020, 5, 28, 19, 24, 43, 413506)

Having said the above, the Celery workers are clearly receiving some render_document tasks, so this is something that seems to happen in either special cases or intermittently.

I did check the queued and active tasks at 5:48pm PT:

>>> from kuma.celery import app
>>> i = app.control.inspect()
>>> i.scheduled()
{'celery@celery-worker-669b54d644-bg4qc': [], 'celery@celery-worker-7bf588675c-kkbzb': [], 'celery@celery-worker-7bf588675c-bkdjr': [], 'celery@celery-worker-669b54d644-wsnpr': [], 'celery@celery-worker-669b54d644-4z5wt': [], 'celery@celery-worker-7bf588675c-p5qhk': [], 'celery@celery-worker-669b54d644-7ccvp': [], 'celery@celery-worker-7bf588675c-c7nmc': []}
>>> i.active()
{'celery@celery-worker-669b54d644-bg4qc': [], 'celery@celery-worker-7bf588675c-kkbzb': [], 'celery@celery-worker-7bf588675c-bkdjr': [], 'celery@celery-worker-669b54d644-4z5wt': [], 'celery@celery-worker-7bf588675c-p5qhk': [], 'celery@celery-worker-669b54d644-wsnpr': [], 'celery@celery-worker-669b54d644-7ccvp': [], 'celery@celery-worker-7bf588675c-c7nmc': []}
>>> i.reserved()
{'celery@celery-worker-669b54d644-bg4qc': [], 'celery@celery-worker-7bf588675c-kkbzb': [], 'celery@celery-worker-7bf588675c-bkdjr': [], 'celery@celery-worker-669b54d644-wsnpr': [], 'celery@celery-worker-7bf588675c-p5qhk': [], 'celery@celery-worker-669b54d644-4z5wt': [], 'celery@celery-worker-669b54d644-7ccvp': [], 'celery@celery-worker-7bf588675c-c7nmc': []}

By the way, I was able to manually kick-off a render_document of https://wiki.developer.mozilla.org/en-US/docs/Web/API/Window/sidebar (via a shift-reload on the Wiki domain while logged in). I saw the task in the Celery-worker log (using papertrail) and it successfully completed.

This is a really disturbing issue, and should be immediately escalated to top priority, since it means that a fundamental part of our system is not working as expected.

[escattone]

Also wanted to record that @a2sheppy also reported the same issue with https://wiki.developer.mozilla.org/en-US/docs/Mozilla/Firefox/Experimental_features

From Slack regarding the above document:

ryan  4:02 PM
@sheppy it looks like your payments api additions eventually worked, but i see you made a lot of changes today. do you remember which ones failed or took a long time to update?
sheppy  4:10 PM
@ryan It was before the payment stuff, it was way back up when I was working on the first three.... anything in the "HTML" section; subsections "Element: <dialog>", "Global attribute: inputmode", and "<link rel="preload">

[escattone]

FYI. I scaled-up the Celery workers from 4 to 6 for the long weekend. I suspect it won't help, but it's simple and it's worth trying until we can determine what's going on.

[escattone]

FYI. I manually kicked-off a re-render of https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-wrap at 8:35pm, and you can see below that the doc.render_scheduled_at was set, but the Celery task was never received by any of the workers (you can see that the render was never started by looking at the stale value for doc.render_started_at and also I never saw the task show-up in papertrail)! I did this on all of the documents above (except for https://wiki.developer.mozilla.org/en-US/docs/Mozilla/Firefox/Experimental_features), and it worked for all of them except for https://wiki.developer.mozilla.org/en-US/docs/Web/CSS/overflow-x.

>>> doc = Document.objects.get(slug="Web/CSS/overflow-wrap", locale="en-US")
>>> doc.render_started_at
datetime.datetime(2020, 6, 18, 4, 52, 30, 285651)
>>> doc.render_scheduled_at
datetime.datetime(2020, 6, 18, 20, 35, 18, 38927)

[atopal]

@escattone Agreed, this should take top priority for the team, at least until we have a clear picture of the root cause and how frequently this happens. I'll mark it as a P1.

[tobinmori]

Thanks @escattone. I'm seeing if PeterBe can take a look at this.

[peterbe]

I have a hunch. If something goes wrong inside the render_document task, what happens is that the revision is saved but the document doesn't get that as its current_revision.

We're currently relying on

subject = "Exception while rendering document %s" % document.pk
mail_admins(subject=subject, message=str(e))

when errors occurred. That should by Sentry instead.

So if anything goes wrong after the save, you end up in this described (this issue) problem in that the revision is saved but not turned into the current revision.

[escattone]

@tobinmori @atopal @peterbe @wbamberg @a2sheppy

The mystery of the lost document render tasks has been solved! @limed turned on the light bulb. The source of the problem was that we left the Celery workers running in the old, idle Kubernetes cluster, and they continued to pull tasks from the same Celery broker (i.e., task queue) used by the Celery workers in the new EKS-based Kubernetes cluster, which is fine, except that the old Kubernetes cluster is in read-only mode, so when one of the Celery workers in the old cluster grabbed a Celery task that needed to write to the DB (like our render tasks), that write would fail and the render task would effectively look like it had never been run. So, in effect, there was roughly a 50/50 chance that a render task would never successfully complete, since it might be grabbed by a Celery worker in the old cluster.

@limed shut down the old cluster completely, so things should be back to normal, and from some testing I've done, that seems to be the case.

Closing this issue.