[11:10:18.345] New invocation is queued and will start shortly
[11:10:20.097] Starting the invocation (attempt 1)
[11:10:20.135] Popped buildset tag "buildset:commit/gitiles/r8.googlesource.com/r8/+/92f09da3f3b5a24746231e9f3acc2024eea1da6a"
[11:10:20.135] Popped gitiles commit info from properties and tags
[11:10:20.135] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[11:10:20.135] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[11:10:20.135] Buildbucket request:
{
  "requestId": "8865109459722112544",
  "builder": {
    "project": "r8",
    "bucket": "ci",
    "builder": "linux-internal_release"
  },
  "properties": {
      "$recipe_engine/scheduler": {
            "hostname": "luci-scheduler.appspot.com",
            "invocation": "8865109459722112544",
            "job": "r8/linux-internal_release",
            "triggers": [
                  {
                        "gitiles": {
                              "ref": "refs/heads/9.0",
                              "repo": "https://r8.googlesource.com/r8",
                              "revision": "92f09da3f3b5a24746231e9f3acc2024eea1da6a"
                            },
                        "id": "https://r8.googlesource.com/r8/+/refs/heads/9.0@92f09da3f3b5a24746231e9f3acc2024eea1da6a",
                        "title": "92f09da3f3b5a24746231e9f3acc2024eea1da6a",
                        "url": "https://r8.googlesource.com/r8/+/92f09da3f3b5a24746231e9f3acc2024eea1da6a"
                      }
                ]
          }
    },
  "gitilesCommit": {
    "host": "r8.googlesource.com",
    "project": "r8",
    "id": "92f09da3f3b5a24746231e9f3acc2024eea1da6a",
    "ref": "refs/heads/9.0"
  },
  "tags": [
    {
      "key": "scheduler_invocation_id",
      "value": "8865109459722112544"
    },
    {
      "key": "scheduler_job_id",
      "value": "r8/linux-internal_release"
    },
    {
      "key": "user_agent",
      "value": "luci-scheduler"
    }
  ],
  "notify": {
    "pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
  }
}
[11:10:20.575] Scheduled build:
{
  "id": "8699679397138463057",
  "builder": {
    "project": "r8",
    "bucket": "ci",
    "builder": "linux-internal_release"
  },
  "number": 1510,
  "createdBy": "project:r8",
  "createTime": "2025-10-29T11:10:20.188959958Z",
  "updateTime": "2025-10-29T11:10:20.188959958Z",
  "status": "SCHEDULED",
  "input": {
    "gitilesCommit": {
      "host": "r8.googlesource.com",
      "project": "r8",
      "id": "92f09da3f3b5a24746231e9f3acc2024eea1da6a",
      "ref": "refs/heads/9.0"
    }
  }
}
[11:10:20.575] Task URL: https://cr-buildbucket.appspot.com/build/8699679397138463057
[11:10:20.575] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:2:0) after 5m12s
[11:10:21.382] Received PubSub notification, asking Buildbucket for the build status
[11:10:21.401] Build status: SCHEDULED
[11:15:32.559] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:2:0)
[11:15:32.586] Build status: SCHEDULED
[11:15:32.586] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:4:0) after 2m41s
[11:18:13.601] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:4:0)
[11:18:13.776] Build status: SCHEDULED
[11:18:13.776] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:5:0) after 7m3s
[11:25:16.831] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:5:0)
[11:25:16.867] Build status: SCHEDULED
[11:25:16.867] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:6:0) after 4m10s
[11:29:26.887] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:6:0)
[11:29:26.903] Build status: SCHEDULED
[11:29:26.903] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:7:0) after 1m10s
[11:30:36.916] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:7:0)
[11:30:36.936] Build status: SCHEDULED
[11:30:36.936] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:8:0) after 5m0s
[11:35:36.955] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:8:0)
[11:35:37.029] Build status: SCHEDULED
[11:35:37.029] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:9:0) after 3m27s
[11:39:04.043] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:9:0)
[11:39:04.183] Build status: SCHEDULED
[11:39:04.184] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:10:0) after 4m52s
[11:43:56.591] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:10:0)
[11:43:56.695] Build status: SCHEDULED
[11:43:56.695] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:11:0) after 9m2s
[11:52:58.707] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:11:0)
[11:52:58.727] Build status: SCHEDULED
[11:52:58.727] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:12:0) after 2m55s
[11:55:53.741] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:12:0)
[11:55:53.756] Build status: SCHEDULED
[11:55:53.756] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:13:0) after 9m31s
[12:05:24.858] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:13:0)
[12:05:24.878] Build status: SCHEDULED
[12:05:24.878] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:14:0) after 2m6s
[12:07:30.959] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:14:0)
[12:07:30.981] Build status: SCHEDULED
[12:07:30.981] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:15:0) after 5m31s
[12:13:02.044] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:15:0)
[12:13:02.062] Build status: SCHEDULED
[12:13:02.062] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:16:0) after 4m34s
[12:17:36.077] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:16:0)
[12:17:36.101] Build status: SCHEDULED
[12:17:36.101] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:17:0) after 4m31s
[12:22:07.149] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:17:0)
[12:22:07.168] Build status: SCHEDULED
[12:22:07.168] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:18:0) after 4m28s
[12:26:35.191] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:18:0)
[12:26:35.215] Build status: SCHEDULED
[12:26:35.215] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:19:0) after 6m17s
[12:32:52.283] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:19:0)
[12:32:52.301] Build status: SCHEDULED
[12:32:52.301] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:20:0) after 6m23s
[12:39:02.119] Received PubSub notification, asking Buildbucket for the build status
[12:39:02.135] Build status: STARTED
[12:39:15.549] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:20:0)
[12:39:15.567] Build status: STARTED
[12:39:15.567] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:22:0) after 6m4s
[12:45:19.682] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:22:0)
[12:45:19.724] Build status: STARTED
[12:45:19.724] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:23:0) after 5m12s
[12:50:31.793] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:23:0)
[12:50:31.835] Build status: STARTED
[12:50:31.835] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:24:0) after 6m52s
[12:57:24.124] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:24:0)
[12:57:24.148] Build status: STARTED
[12:57:24.148] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:25:0) after 6m54s
[13:04:18.216] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:25:0)
[13:04:18.232] Build status: STARTED
[13:04:18.232] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:26:0) after 8m38s
[13:12:56.296] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:26:0)
[13:12:56.310] Build status: STARTED
[13:12:56.310] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:27:0) after 2m36s
[13:15:32.468] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:27:0)
[13:15:32.492] Build status: STARTED
[13:15:32.492] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:28:0) after 7m43s
[13:23:15.596] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:28:0)
[13:23:15.616] Build status: STARTED
[13:23:15.616] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:29:0) after 4m55s
[13:28:10.639] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:29:0)
[13:28:10.674] Build status: STARTED
[13:28:10.674] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:30:0) after 1m31s
[13:29:41.732] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:30:0)
[13:29:41.755] Build status: STARTED
[13:29:41.755] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:31:0) after 6m33s
[13:36:14.767] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:31:0)
[13:36:14.782] Build status: STARTED
[13:36:14.782] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:32:0) after 1m15s
[13:37:29.849] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:32:0)
[13:37:29.866] Build status: STARTED
[13:37:29.866] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:33:0) after 8m53s
[13:46:22.880] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:33:0)
[13:46:22.908] Build status: STARTED
[13:46:22.908] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:34:0) after 9m3s
[13:55:25.967] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:34:0)
[13:55:26.226] Build status: STARTED
[13:55:26.226] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:35:0) after 8m2s
[14:03:28.244] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:35:0)
[14:03:28.276] Build status: STARTED
[14:03:28.276] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:36:0) after 6m40s
[14:10:08.294] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:36:0)
[14:10:08.311] Build status: STARTED
[14:10:08.311] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:37:0) after 5m24s
[14:15:32.377] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:37:0)
[14:15:32.395] Build status: STARTED
[14:15:32.395] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:38:0) after 3m37s
[14:19:09.415] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:38:0)
[14:19:09.437] Build status: STARTED
[14:19:09.437] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:39:0) after 3m37s
[14:22:46.454] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:39:0)
[14:22:46.471] Build status: STARTED
[14:22:46.471] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:40:0) after 5m31s
[14:28:17.501] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:40:0)
[14:28:17.518] Build status: STARTED
[14:28:17.518] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:41:0) after 2m50s
[14:31:07.538] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:41:0)
[14:31:07.560] Build status: STARTED
[14:31:07.561] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:42:0) after 5m32s
[14:36:39.530] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:42:0)
[14:36:39.547] Build status: STARTED
[14:36:39.547] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:43:0) after 6m49s
[14:43:28.598] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:43:0)
[14:43:28.631] Build status: STARTED
[14:43:28.631] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:44:0) after 1m1s
[14:44:29.787] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:44:0)
[14:44:29.814] Build status: STARTED
[14:44:29.815] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:45:0) after 1m23s
[14:45:52.832] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:45:0)
[14:45:52.898] Build status: STARTED
[14:45:52.898] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:46:0) after 3m49s
[14:49:41.914] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:46:0)
[14:49:41.936] Build status: STARTED
[14:49:41.936] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:47:0) after 4m19s
[14:54:00.953] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:47:0)
[14:54:01.128] Build status: STARTED
[14:54:01.128] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:48:0) after 6m14s
[15:00:15.193] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:48:0)
[15:00:15.255] Build status: STARTED
[15:00:15.255] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:49:0) after 9m49s
[15:10:04.270] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:49:0)
[15:10:04.385] Build status: STARTED
[15:10:04.385] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:50:0) after 8m2s
[15:18:06.387] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:50:0)
[15:18:06.422] Build status: STARTED
[15:18:06.427] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:51:0) after 9m2s
[15:27:08.444] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:51:0)
[15:27:08.461] Build status: STARTED
[15:27:08.461] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:52:0) after 4m39s
[15:31:47.477] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:52:0)
[15:31:47.535] Build status: STARTED
[15:31:47.535] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:53:0) after 3m13s
[15:35:00.700] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:53:0)
[15:35:00.726] Build status: STARTED
[15:35:00.726] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:54:0) after 3m59s
[15:38:59.756] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:54:0)
[15:38:59.772] Build status: STARTED
[15:38:59.773] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:55:0) after 8m21s
[15:47:20.790] Handling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:55:0)
[15:47:20.810] Build status: STARTED
[15:47:20.810] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal_release:8865109459722112544:56:0) after 1m40s
[15:48:52.394] Received PubSub notification, asking Buildbucket for the build status
[15:48:52.415] Build:
{
  "id": "8699679397138463057",
  "builder": {
    "project": "r8",
    "bucket": "ci",
    "builder": "linux-internal_release"
  },
  "number": 1510,
  "createdBy": "project:r8",
  "createTime": "2025-10-29T11:10:20.188959958Z",
  "startTime": "2025-10-29T12:39:01.533751485Z",
  "endTime": "2025-10-29T15:48:52.206453657Z",
  "updateTime": "2025-10-29T15:48:52.206453657Z",
  "status": "SUCCESS",
  "input": {
    "gitilesCommit": {
      "host": "r8.googlesource.com",
      "project": "r8",
      "id": "92f09da3f3b5a24746231e9f3acc2024eea1da6a",
      "ref": "refs/heads/9.0"
    }
  }
}
[15:48:52.415] Invocation finished in 4h38m34.074546433s with status SUCCEEDED