[16:22:17.590] New invocation is queued and will start shortly
[16:22:18.656] Starting the invocation (attempt 1)
[16:22:18.682] Popped buildset tag "buildset:commit/gitiles/r8.googlesource.com/r8/+/b0653172f6e2a944a8082cf25264e5e562d3b6e6"
[16:22:18.682] Popped gitiles commit info from properties and tags
[16:22:18.682] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[16:22:18.682] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[16:22:18.682] Buildbucket request:
{
  "requestId": "8864908637241373488",
  "builder": {
    "project": "r8",
    "bucket": "ci",
    "builder": "linux-dev"
  },
  "properties": {
      "$recipe_engine/scheduler": {
            "hostname": "luci-scheduler.appspot.com",
            "invocation": "8864908637241373488",
            "job": "r8/linux-dev",
            "triggers": [
                  {
                        "gitiles": {
                              "ref": "refs/heads/main",
                              "repo": "https://r8.googlesource.com/r8",
                              "revision": "b0653172f6e2a944a8082cf25264e5e562d3b6e6"
                            },
                        "id": "https://r8.googlesource.com/r8/+/refs/heads/main@b0653172f6e2a944a8082cf25264e5e562d3b6e6",
                        "title": "b0653172f6e2a944a8082cf25264e5e562d3b6e6",
                        "url": "https://r8.googlesource.com/r8/+/b0653172f6e2a944a8082cf25264e5e562d3b6e6"
                      }
                ]
          }
    },
  "gitilesCommit": {
    "host": "r8.googlesource.com",
    "project": "r8",
    "id": "b0653172f6e2a944a8082cf25264e5e562d3b6e6",
    "ref": "refs/heads/main"
  },
  "tags": [
    {
      "key": "scheduler_invocation_id",
      "value": "8864908637241373488"
    },
    {
      "key": "scheduler_job_id",
      "value": "r8/linux-dev"
    },
    {
      "key": "user_agent",
      "value": "luci-scheduler"
    }
  ],
  "notify": {
    "pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
  }
}
[16:22:19.135] Scheduled build:
{
  "id": "8699478575375649825",
  "builder": {
    "project": "r8",
    "bucket": "ci",
    "builder": "linux-dev"
  },
  "number": 1033,
  "createdBy": "project:r8",
  "createTime": "2025-10-31T16:22:18.745647960Z",
  "updateTime": "2025-10-31T16:22:18.745647960Z",
  "status": "SCHEDULED",
  "input": {
    "gitilesCommit": {
      "host": "r8.googlesource.com",
      "project": "r8",
      "id": "b0653172f6e2a944a8082cf25264e5e562d3b6e6",
      "ref": "refs/heads/main"
    }
  }
}
[16:22:19.135] Task URL: https://cr-buildbucket.appspot.com/build/8699478575375649825
[16:22:19.135] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:2:0) after 5m57s
[16:22:20.073] Received PubSub notification, asking Buildbucket for the build status
[16:22:20.125] Build status: SCHEDULED
[16:22:25.915] Received PubSub notification, asking Buildbucket for the build status
[16:22:25.985] Build status: STARTED
[16:28:16.150] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:2:0)
[16:28:16.170] Build status: STARTED
[16:28:16.170] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:5:0) after 4m27s
[16:32:43.189] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:5:0)
[16:32:43.204] Build status: STARTED
[16:32:43.204] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:6:0) after 7m37s
[16:40:20.250] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:6:0)
[16:40:20.267] Build status: STARTED
[16:40:20.267] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:7:0) after 5m23s
[16:45:43.289] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:7:0)
[16:45:43.309] Build status: STARTED
[16:45:43.309] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:8:0) after 8m37s
[16:54:20.321] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:8:0)
[16:54:20.374] Build status: STARTED
[16:54:20.374] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:9:0) after 5m30s
[16:59:50.388] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:9:0)
[16:59:50.405] Build status: STARTED
[16:59:50.405] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:10:0) after 1m4s
[17:00:54.420] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:10:0)
[17:00:54.437] Build status: STARTED
[17:00:54.437] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:11:0) after 4m18s
[17:05:12.449] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:11:0)
[17:05:12.470] Build status: STARTED
[17:05:12.470] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:12:0) after 1m13s
[17:06:25.556] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:12:0)
[17:06:25.600] Build status: STARTED
[17:06:25.600] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:13:0) after 1m57s
[17:08:22.684] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:13:0)
[17:08:22.707] Build status: STARTED
[17:08:22.707] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:14:0) after 2m30s
[17:10:52.721] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:14:0)
[17:10:52.740] Build status: STARTED
[17:10:52.740] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:15:0) after 6m19s
[17:17:11.750] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:15:0)
[17:17:11.779] Build status: STARTED
[17:17:11.779] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:16:0) after 6m26s
[17:23:37.908] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:16:0)
[17:23:37.924] Build status: STARTED
[17:23:37.924] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:17:0) after 4m15s
[17:27:52.907] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:17:0)
[17:27:52.968] Build status: STARTED
[17:27:52.968] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:18:0) after 5m55s
[17:33:47.981] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:18:0)
[17:33:47.996] Build status: STARTED
[17:33:47.996] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:19:0) after 7m36s
[17:41:24.028] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:19:0)
[17:41:24.049] Build status: STARTED
[17:41:24.050] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:20:0) after 2m46s
[17:44:10.074] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:20:0)
[17:44:10.097] Build status: STARTED
[17:44:10.097] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:21:0) after 1m35s
[17:45:45.109] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:21:0)
[17:45:45.131] Build status: STARTED
[17:45:45.131] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:22:0) after 2m11s
[17:47:56.184] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:22:0)
[17:47:56.229] Build status: STARTED
[17:47:56.229] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:23:0) after 7m40s
[17:55:36.243] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:23:0)
[17:55:36.335] Build status: STARTED
[17:55:36.335] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:24:0) after 6m49s
[18:02:25.358] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:24:0)
[18:02:25.373] Build status: STARTED
[18:02:25.373] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:25:0) after 1m47s
[18:04:12.431] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:25:0)
[18:04:12.495] Build status: STARTED
[18:04:12.495] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:26:0) after 3m40s
[18:07:52.562] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:26:0)
[18:07:52.608] Build status: STARTED
[18:07:52.608] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:27:0) after 4m7s
[18:11:59.621] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:27:0)
[18:11:59.636] Build status: STARTED
[18:11:59.636] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:28:0) after 1m23s
[18:13:22.650] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:28:0)
[18:13:22.666] Build status: STARTED
[18:13:22.666] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:29:0) after 6m14s
[18:19:36.681] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:29:0)
[18:19:36.699] Build status: STARTED
[18:19:36.699] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:30:0) after 8m55s
[18:28:31.933] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:30:0)
[18:28:31.979] Build status: STARTED
[18:28:31.979] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:31:0) after 6m12s
[18:34:44.045] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:31:0)
[18:34:44.069] Build status: STARTED
[18:34:44.070] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:32:0) after 1m15s
[18:35:59.038] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:32:0)
[18:35:59.067] Build status: STARTED
[18:35:59.067] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:33:0) after 9m15s
[18:45:14.079] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:33:0)
[18:45:14.100] Build status: STARTED
[18:45:14.100] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:34:0) after 1m3s
[18:46:17.161] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:34:0)
[18:46:17.181] Build status: STARTED
[18:46:17.181] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:35:0) after 4m42s
[18:50:59.193] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:35:0)
[18:50:59.208] Build status: STARTED
[18:50:59.208] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:36:0) after 4m6s
[18:55:05.252] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:36:0)
[18:55:05.323] Build status: STARTED
[18:55:05.323] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:37:0) after 5m25s
[19:00:30.336] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:37:0)
[19:00:30.365] Build status: STARTED
[19:00:30.365] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:38:0) after 4m5s
[19:04:35.427] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:38:0)
[19:04:35.446] Build status: STARTED
[19:04:35.446] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:39:0) after 7m6s
[19:11:41.513] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:39:0)
[19:11:41.545] Build status: STARTED
[19:11:41.545] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:40:0) after 6m20s
[19:18:01.565] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:40:0)
[19:18:01.585] Build status: STARTED
[19:18:01.585] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:41:0) after 7m32s
[19:25:33.647] Handling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:41:0)
[19:25:33.663] Build status: STARTED
[19:25:33.663] Scheduling timer "check-buildbucket-build-status" (r8/linux-dev:8864908637241373488:42:0) after 4m44s
[19:27:55.693] Received PubSub notification, asking Buildbucket for the build status
[19:27:55.713] Build:
{
  "id": "8699478575375649825",
  "builder": {
    "project": "r8",
    "bucket": "ci",
    "builder": "linux-dev"
  },
  "number": 1033,
  "createdBy": "project:r8",
  "createTime": "2025-10-31T16:22:18.745647960Z",
  "startTime": "2025-10-31T16:22:24.928409837Z",
  "endTime": "2025-10-31T19:27:55.527045015Z",
  "updateTime": "2025-10-31T19:27:55.527045015Z",
  "status": "SUCCESS",
  "input": {
    "gitilesCommit": {
      "host": "r8.googlesource.com",
      "project": "r8",
      "id": "b0653172f6e2a944a8082cf25264e5e562d3b6e6",
      "ref": "refs/heads/main"
    }
  }
}
[19:27:55.713] Invocation finished in 3h5m38.130943069s with status SUCCEEDED