Builds: save task_executed_at to help debugging (#12500)

Save the datetime when the build was executed by a worker and log a
warning if it's bigger than 10 minutes (we can adjust this number as we
want). Note that 5 minutes is the default retry time.

This is a POC to help debugging
#12472

This data together with other logs like
* "Delaying tasks due to concurrency limit."
* "Retrying this task."

could help us to understand what's going on here.

Author: humitos

readthedocs/builds/migrations/0065_task_executed_at.py

@@ -0,0 +1,23 @@
+# Generated by Django 5.2.6 on 2025-09-30 12:39
+
+from django.db import migrations
+from django.db import models
+from django_safemigrate import Safe
+
+
+class Migration(migrations.Migration):
+    safe = Safe.before_deploy()
+
+    dependencies = [
+        ("builds", "0064_healthcheck"),
+    ]
+
+    operations = [
+        migrations.AddField(
+            model_name="build",
+            name="task_executed_at",
+            field=models.DateTimeField(
+                blank=True, null=True, verbose_name="Task executed at datetime"
+            ),
+        ),
+    ]

readthedocs/builds/models.py

@@ -714,6 +714,11 @@ class Build(models.Model):
         null=True,
         blank=True,
     )
+    task_executed_at = models.DateTimeField(
+        _("Task executed at datetime"),
+        null=True,
+        blank=True,
+    )
 
     notifications = GenericRelation(
         Notification,
@@ -779,7 +784,7 @@ def config(self):
         """
         # TODO: now that we are using a proper JSONField here, we could
         # probably change this field to be a ForeignKey to avoid repeating the
-        # config file over and over again and re-use them to save db data as
+        # config file over and over again and reuse them to save db data as
         # well
         if self._config and self.CONFIG_KEY in self._config:
             return Build.objects.only("_config").get(pk=self._config[self.CONFIG_KEY])._config
@@ -977,7 +982,7 @@ class BuildCommandResultMixin:
     Mixin for common command result methods/properties.
 
     Shared methods between the database model :py:class:`BuildCommandResult` and
-    non-model respresentations of build command results from the API
+    non-model representations of build command results from the API
     """
 
     @property

readthedocs/projects/tasks/builds.py

@@ -5,6 +5,7 @@
 rebuilding documentation.
 """
 
+import datetime
 import os
 import shutil
 import signal
@@ -410,6 +411,19 @@ def before_start(self, task_id, args, kwargs):
             version_slug=self.data.version.slug,
         )
 
+        # Log a warning if the task took more than 10 minutes to be retried
+        if self.data.build["task_executed_at"]:
+            task_executed_at = datetime.datetime.fromisoformat(self.data.build["task_executed_at"])
+            delta = timezone.now() - task_executed_at
+            if delta > timezone.timedelta(minutes=10):
+                log.warning(
+                    "This task waited more than 10 minutes to be retried.",
+                    delta_minutes=round(delta.seconds / 60, 1),
+                )
+
+        # Save when the task was executed by a builder
+        self.data.build["task_executed_at"] = timezone.now()
+
         # Enable scale-in protection on this instance
         #
         # TODO: move this to the beginning of this method
@@ -727,7 +741,9 @@ def on_retry(self, exc, task_id, args, kwargs, einfo):
                 message_id=BuildMaxConcurrencyError.LIMIT_REACHED,
                 format_values=format_values,
             )
-            self.update_build(state=BUILD_STATE_TRIGGERED)
+
+        # Always update the build on retry
+        self.update_build(state=BUILD_STATE_TRIGGERED)
 
     def after_return(self, status, retval, task_id, args, kwargs, einfo):
         """

readthedocs/projects/tests/mockers.py

@@ -186,6 +186,7 @@ def _mock_api(self):
                 "id": self.build.pk,
                 "state": BUILD_STATE_TRIGGERED,
                 "commit": self.build.commit,
+                "task_executed_at": self.build.task_executed_at,
             },
             headers=headers,
         )

readthedocs/projects/tests/test_build_tasks.py

@@ -537,6 +537,7 @@ def test_successful_build(
             "commit": "a1b2c3",
             "error": "",
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
         }
 
         # Update build state: installing
@@ -545,6 +546,7 @@ def test_successful_build(
             "state": "installing",
             "commit": "a1b2c3",
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "readthedocs_yaml_path": None,
             "error": "",
             # We update the `config` field at the same time we send the
@@ -618,6 +620,7 @@ def test_successful_build(
             "readthedocs_yaml_path": None,
             "config": mock.ANY,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "error": "",
         }
         # Update build state: uploading
@@ -628,6 +631,7 @@ def test_successful_build(
             "readthedocs_yaml_path": None,
             "config": mock.ANY,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "error": "",
         }
         # Update version state
@@ -654,6 +658,7 @@ def test_successful_build(
             "readthedocs_yaml_path": None,
             "config": mock.ANY,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "length": mock.ANY,
             "success": True,
             "error": "",
@@ -811,6 +816,7 @@ def test_successful_build_with_temporary_s3_credentials(
             "commit": "a1b2c3",
             "error": "",
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
         }
 
         # Update build state: installing
@@ -819,6 +825,7 @@ def test_successful_build_with_temporary_s3_credentials(
             "state": "installing",
             "commit": "a1b2c3",
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "readthedocs_yaml_path": None,
             "error": "",
             # We update the `config` field at the same time we send the
@@ -900,6 +907,7 @@ def test_successful_build_with_temporary_s3_credentials(
             "readthedocs_yaml_path": None,
             "config": mock.ANY,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "error": "",
         }
         # Update build state: uploading
@@ -910,6 +918,7 @@ def test_successful_build_with_temporary_s3_credentials(
             "readthedocs_yaml_path": None,
             "config": mock.ANY,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "error": "",
         }
 
@@ -944,6 +953,7 @@ def test_successful_build_with_temporary_s3_credentials(
             "readthedocs_yaml_path": None,
             "config": mock.ANY,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "length": mock.ANY,
             "success": True,
             "error": "",
@@ -1031,6 +1041,7 @@ def test_failed_build(
         assert build_status_request.path == "/api/v2/build/1/"
         assert build_status_request.json() == {
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "commit": self.build.commit,
             "error": "",  # We are not sending ``error`` anymore
             "id": self.build.pk,
@@ -1085,6 +1096,7 @@ def test_cancelled_build(
         assert build_status_request.path == "/api/v2/build/1/"
         assert build_status_request.json() == {
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "commit": self.build.commit,
             "error": "",  # We are not sending ``error`` anymore
             "id": self.build.pk,
@@ -2968,6 +2980,7 @@ def test_config_file_exception(self, load_yaml_config):
             "error": "",  # We not sending "error" anymore
             "success": False,
             "builder": mock.ANY,
+            "task_executed_at": mock.ANY,
             "length": 0,
         }