Build: Build command HttpNotFoundError: Client Error 404

[sentry-io]

It seems like there is some race condition when posting a build command from inside a build that has restarted automatically -- long running builds that celery kills after 1 hour and "restarts".

The issue can be summarized as:

• Build starts and maybe sphinx-build step takes more than 1 hour. Celery kills this build. This is a separate, known issue.
• On restarting the task, at some point posting a build command will result in a 404 ¹.
• This causes the build to restart yet again, in a further broken state. Not sure how to explain this yet.
• Eventually the build also fails due to 403 from the build token expiring.

The underlying problem is hard to describe and it might be suffering from a timing issue as well. For one of the events on that issue, the build currently has 3 build commands:

In [11]: list(Build.objects.get(pk=28816462).commands.values_list("pk", flat=True))
Out[11]: [278037179, 278037193, 278037205]

But the Sentry exception notes we were trying to patch() to this build command:

Client Error 404: https://{host}/api/v2/command/278032405/

If we inspect build command 278032405, it doesn't exist at all.

Footnotes

1. Sentry Issue: READTHEDOCS-ORG-T7M ↩

[agjohnson]

I think I understand what is happening here. If you look at the build logs and pay attention to the process.id of the log lines, you'll notice there are two builds overlapping. I assumed builds properly restarted in this scenario, but this is not that.

From https://onenr.io/0ZQWqyWYrRW:

• The only process.id is 1345 up until sphinx-build command, which takes a long time.
• At the 1 hour mark, we start a new task. It has process.id 1704.
• At the start of this new task, _reset_build() is called.
• The command in pid 1345 finally fails and 1345 tries to post the build command.
• The build command id was removed with _reset_build() so we can't patch it anymore. Previously this worked because we were always using post()
• Process id 1345 fails the build and finished
• Build token is revoked here I'm guessing?
• Process id 1704 tries to post new commands and failed with 403
• Build is finally marked failing.

So previously, this was working because the first build process would be able to mark the build as passing. While the second build would continue rebuilding again, and hopefully eventually succeed without Celery killing the process again, it should eventually be marked as pass.

A temporary fix is to post() on patch() failure. A long term fix is to avoid overlapping builds and Celery retry.

[agjohnson]

I've hotfixed this in 60d1bf3 and applied it directly to rel/relcorp. Because we changed this logic again in main already I couldn't branch there. We'll need to replicate this hotfix in main for release.

[ericholscher]

What is causing the build to start again after 1 hour? Is it a celery task timeout and is failing to kill the task, but then starts a new one?

[ericholscher]

Seems like this is probably it:

readthedocs.org/readthedocs/settings/base.py

Line 499 in c1cb4ee

CELERYD_TASK_TIME_LIMIT = 60 * 60 # 60 minutes

But we're explicitly setting it to 2 hours here:

readthedocs.org/readthedocs/core/utils/__init__.py

Line 95 in c1cb4ee

time_limit = 7200

[agjohnson]

Yeah that needs some more investigation, I'm not entirely sure. It's probably the key to understanding why builds get stuck in a restart loop.

The celery task time limit might be part of this. I was testing with builds that have 2 and 3 hour project time limits though, so 1 hour restart doesn't quite fit here.

It seems more like Celery is considering the task dead or the connection closed after 1 hour, as it does allow the first task to continue execution. I don't know what setting this is though, but there are some settings around healthchecks and connection loss.

To test and debug, I think we could set up a project with a 3 hour time limit, and execute two build jobs: sit idle for less than 60m, sit idle for more than 60m -- ie 50/70min. I would guess the first step would consistently pass and then after 60m on the second step we'll see a duplicated build. I don't think we've been able to repro this locally yet, so that would be rather helpful if we could.

@humitos pointed out that AWS instances have their own time limit on shutdown in the past, and figured that might be a source of retrying. But I think the timing above shows it's not that the first instance is going away, so we can probably rule this out.

[agjohnson]

Yup, as I figured Celery task time limit look to be set high enough:

soft_time_limit=10800 task_id=6c9c008d-d9d2-4fd2-a18e-e6e1f9d46a4e time_limit=12960

I was able to get the build to fail ~65m into a command, well short of the limit. It looks like the build did start to build on a different process but the overlap was narrow enough that the second process didn't make it past the concurrency check against the API.

I'm testing on my local instance with test-builds@timeout-debug and a project time limit of 3 hours. The timeout debug runs a 90 minute command. I started running a 50m and 70m like described above and it executed everything as I described. Running a 90min command should give a failure that roughly emulates what projects with long build times are noticing.

[agjohnson]

This setting seems worth testing:

https://docs.celeryq.dev/en/stable/getting-started/backends-and-brokers/redis.html#visibility-timeout

The visibility timeout defines the number of seconds to wait for the worker to acknowledge the task before the message is redelivered to another worker. Be sure to see Caveats below.

The default visibility timeout for Redis is 1 hour.