[00:15:39.091] New invocation is queued and will start shortly
[00:15:40.241] Starting the invocation (attempt 1)
[00:15:40.274] Popped buildset tag "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/a6558c20d1a4ee8d8c88de176d0bb9ca6ecead3a"
[00:15:40.274] Popped gitiles commit info from properties and tags
[00:15:40.274] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[00:15:40.274] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[00:15:40.275] Buildbucket request:
{
  "requestId": "8865875422741725584",
  "builder": {
    "project": "chromium",
    "bucket": "ci",
    "builder": "chromeos-arm64-generic-rel"
  },
  "properties": {
    },
  "gitilesCommit": {
    "host": "chromium.googlesource.com",
    "project": "chromium/src",
    "id": "a6558c20d1a4ee8d8c88de176d0bb9ca6ecead3a",
    "ref": "refs/heads/main"
  },
  "tags": [
    {
      "key": "scheduler_invocation_id",
      "value": "8865875422741725584"
    },
    {
      "key": "scheduler_job_id",
      "value": "chromium/chromeos-arm64-generic-rel"
    },
    {
      "key": "user_agent",
      "value": "luci-scheduler"
    }
  ],
  "notify": {
    "pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
  }
}
[00:15:40.734] Scheduled build:
{
  "id": "8700445360781204401",
  "builder": {
    "project": "chromium",
    "bucket": "ci",
    "builder": "chromeos-arm64-generic-rel"
  },
  "number": 56211,
  "createdBy": "project:chromium",
  "createTime": "2025-10-21T00:15:40.335470575Z",
  "updateTime": "2025-10-21T00:15:40.335470575Z",
  "status": "SCHEDULED",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "a6558c20d1a4ee8d8c88de176d0bb9ca6ecead3a",
      "ref": "refs/heads/main"
    }
  }
}
[00:15:40.734] Task URL: https://cr-buildbucket.appspot.com/build/8700445360781204401
[00:15:40.734] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:2:0) after 9m42s
[00:15:41.709] Received PubSub notification, asking Buildbucket for the build status
[00:15:41.737] Build status: SCHEDULED
[00:16:40.965] Received PubSub notification, asking Buildbucket for the build status
[00:16:41.002] Build status: STARTED
[00:25:22.754] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:2:0)
[00:25:22.779] Build status: STARTED
[00:25:22.780] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:5:0) after 6m4s
[00:31:26.794] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:5:0)
[00:31:26.826] Build status: STARTED
[00:31:26.826] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:6:0) after 3m10s
[00:34:36.810] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:6:0)
[00:34:36.883] Build status: STARTED
[00:34:36.883] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:7:0) after 2m17s
[00:36:53.898] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:7:0)
[00:36:53.924] Build status: STARTED
[00:36:53.924] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:8:0) after 4m55s
[00:41:48.985] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:8:0)
[00:41:49.088] Build status: STARTED
[00:41:49.088] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:9:0) after 6m32s
[00:48:21.135] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:9:0)
[00:48:21.150] Build status: STARTED
[00:48:21.150] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:10:0) after 1m30s
[00:49:51.137] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:10:0)
[00:49:51.199] Build status: STARTED
[00:49:51.199] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:11:0) after 4m36s
[00:54:27.198] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:11:0)
[00:54:27.214] Build status: STARTED
[00:54:27.214] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:12:0) after 7m18s
[01:01:45.230] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:12:0)
[01:01:45.251] Build status: STARTED
[01:01:45.251] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:13:0) after 4m24s
[01:06:09.252] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:13:0)
[01:06:09.272] Build status: STARTED
[01:06:09.272] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:14:0) after 2m22s
[01:08:31.328] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:14:0)
[01:08:31.535] Build status: STARTED
[01:08:31.535] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:15:0) after 6m35s
[01:15:06.661] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:15:0)
[01:15:06.674] Build status: STARTED
[01:15:06.674] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:16:0) after 1m36s
[01:16:42.689] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:16:0)
[01:16:42.702] Build status: STARTED
[01:16:42.702] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:17:0) after 5m33s
[01:22:15.809] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:17:0)
[01:22:15.825] Build status: STARTED
[01:22:15.825] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:18:0) after 2m21s
[01:24:36.870] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:18:0)
[01:24:36.890] Build status: STARTED
[01:24:36.890] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:19:0) after 4m49s
[01:29:25.966] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:19:0)
[01:29:25.982] Build status: STARTED
[01:29:25.982] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:20:0) after 3m11s
[01:32:36.982] Handling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:20:0)
[01:32:37.008] Build status: STARTED
[01:32:37.008] Scheduling timer "check-buildbucket-build-status" (chromium/chromeos-arm64-generic-rel:8865875422741725584:21:0) after 4m13s
[01:34:58.857] Received PubSub notification, asking Buildbucket for the build status
[01:34:58.872] Build:
{
  "id": "8700445360781204401",
  "builder": {
    "project": "chromium",
    "bucket": "ci",
    "builder": "chromeos-arm64-generic-rel"
  },
  "number": 56211,
  "createdBy": "project:chromium",
  "createTime": "2025-10-21T00:15:40.335470575Z",
  "startTime": "2025-10-21T00:16:40.335752021Z",
  "endTime": "2025-10-21T01:34:58.327195809Z",
  "updateTime": "2025-10-21T01:34:58.327195809Z",
  "status": "SUCCESS",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "a6558c20d1a4ee8d8c88de176d0bb9ca6ecead3a",
      "ref": "refs/heads/main"
    }
  }
}
[01:34:58.872] Invocation finished in 1h19m19.790980006s with status SUCCEEDED