[14:39:09.584] New invocation is queued and will start shortly
[14:39:10.787] Starting the invocation (attempt 1)
[14:39:10.825] Popped buildset tag "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/f38463fd645d12a2eb07cd4dae77afabf2ba4139"
[14:39:10.825] Popped gitiles commit info from properties and tags
[14:39:10.825] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[14:39:10.825] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[14:39:10.825] Buildbucket request:
{
  "requestId": "8866274080333782512",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win-arm64-rel"
  },
  "properties": {
      "$recipe_engine/scheduler": {
            "hostname": "luci-scheduler.appspot.com",
            "invocation": "8866274080333782512",
            "job": "chromium-m140/win-arm64-rel",
            "triggers": [
                  {
                        "gitiles": {
                              "ref": "refs/branch-heads/7339",
                              "repo": "https://chromium.googlesource.com/chromium/src",
                              "revision": "f38463fd645d12a2eb07cd4dae77afabf2ba4139"
                            },
                        "id": "https://chromium.googlesource.com/chromium/src/+/refs/branch-heads/7339@f38463fd645d12a2eb07cd4dae77afabf2ba4139",
                        "title": "f38463fd645d12a2eb07cd4dae77afabf2ba4139",
                        "url": "https://chromium.googlesource.com/chromium/src/+/f38463fd645d12a2eb07cd4dae77afabf2ba4139"
                      }
                ]
          }
    },
  "gitilesCommit": {
    "host": "chromium.googlesource.com",
    "project": "chromium/src",
    "id": "f38463fd645d12a2eb07cd4dae77afabf2ba4139",
    "ref": "refs/branch-heads/7339"
  },
  "tags": [
    {
      "key": "scheduler_invocation_id",
      "value": "8866274080333782512"
    },
    {
      "key": "scheduler_job_id",
      "value": "chromium-m140/win-arm64-rel"
    },
    {
      "key": "user_agent",
      "value": "luci-scheduler"
    }
  ],
  "notify": {
    "pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
  }
}
[14:39:11.401] Scheduled build:
{
  "id": "8700844018305268977",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win-arm64-rel"
  },
  "number": 768,
  "createdBy": "project:chromium-m140",
  "createTime": "2025-10-16T14:39:10.893374936Z",
  "updateTime": "2025-10-16T14:39:10.893374936Z",
  "status": "SCHEDULED",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "f38463fd645d12a2eb07cd4dae77afabf2ba4139",
      "ref": "refs/branch-heads/7339"
    }
  }
}
[14:39:11.401] Task URL: https://cr-buildbucket.appspot.com/build/8700844018305268977
[14:39:11.401] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:2:0) after 9m57s
[14:39:12.343] Received PubSub notification, asking Buildbucket for the build status
[14:39:12.370] Build status: SCHEDULED
[14:49:08.480] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:2:0)
[14:49:08.496] Build status: SCHEDULED
[14:49:08.496] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:4:0) after 5m51s
[14:54:59.582] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:4:0)
[14:54:59.598] Build status: SCHEDULED
[14:54:59.598] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:5:0) after 1m46s
[14:55:09.299] Received PubSub notification, asking Buildbucket for the build status
[14:55:09.317] Build status: STARTED
[14:56:45.582] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:5:0)
[14:56:45.608] Build status: STARTED
[14:56:45.608] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:7:0) after 9m16s
[15:06:01.621] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:7:0)
[15:06:01.652] Build status: STARTED
[15:06:01.653] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:8:0) after 3m50s
[15:09:51.638] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:8:0)
[15:09:51.691] Build status: STARTED
[15:09:51.691] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:9:0) after 9m38s
[15:19:29.755] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:9:0)
[15:19:29.799] Build status: STARTED
[15:19:29.799] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:10:0) after 4m9s
[15:23:38.836] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:10:0)
[15:23:38.900] Build status: STARTED
[15:23:38.900] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:11:0) after 7m6s
[15:30:44.960] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:11:0)
[15:30:44.984] Build status: STARTED
[15:30:44.984] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:12:0) after 6m50s
[15:37:35.049] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:12:0)
[15:37:35.124] Build status: STARTED
[15:37:35.124] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:13:0) after 1m15s
[15:38:50.112] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:13:0)
[15:38:50.133] Build status: STARTED
[15:38:50.133] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:14:0) after 7m15s
[15:46:05.146] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:14:0)
[15:46:05.166] Build status: STARTED
[15:46:05.166] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:15:0) after 7m20s
[15:53:25.202] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:15:0)
[15:53:25.243] Build status: STARTED
[15:53:25.243] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:16:0) after 3m24s
[15:56:49.294] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:16:0)
[15:56:49.327] Build status: STARTED
[15:56:49.327] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:17:0) after 1m59s
[15:58:48.339] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:17:0)
[15:58:48.406] Build status: STARTED
[15:58:48.406] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:18:0) after 9m32s
[16:08:20.493] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:18:0)
[16:08:20.512] Build status: STARTED
[16:08:20.512] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:19:0) after 2m24s
[16:10:44.527] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:19:0)
[16:10:44.601] Build status: STARTED
[16:10:44.602] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:20:0) after 9m28s
[16:20:12.621] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:20:0)
[16:20:12.643] Build status: STARTED
[16:20:12.643] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:21:0) after 3m37s
[16:23:49.714] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:21:0)
[16:23:49.762] Build status: STARTED
[16:23:49.762] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:22:0) after 8m52s
[16:32:41.816] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:22:0)
[16:32:41.834] Build status: STARTED
[16:32:41.835] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:23:0) after 9m48s
[16:42:29.929] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:23:0)
[16:42:29.962] Build status: STARTED
[16:42:29.962] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:24:0) after 2m51s
[16:45:20.973] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:24:0)
[16:45:21.001] Build status: STARTED
[16:45:21.001] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:25:0) after 1m35s
[16:46:56.025] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:25:0)
[16:46:56.043] Build status: STARTED
[16:46:56.043] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:26:0) after 4m4s
[16:51:00.143] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:26:0)
[16:51:00.175] Build status: STARTED
[16:51:00.175] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:27:0) after 3m31s
[16:54:31.272] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:27:0)
[16:54:31.289] Build status: STARTED
[16:54:31.289] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:28:0) after 2m12s
[16:56:43.303] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:28:0)
[16:56:43.319] Build status: STARTED
[16:56:43.319] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:29:0) after 7m4s
[17:03:47.330] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:29:0)
[17:03:47.347] Build status: STARTED
[17:03:47.347] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:30:0) after 1m49s
[17:05:36.462] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:30:0)
[17:05:36.480] Build status: STARTED
[17:05:36.480] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:31:0) after 4m29s
[17:10:05.580] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:31:0)
[17:10:05.597] Build status: STARTED
[17:10:05.598] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:32:0) after 4m12s
[17:14:17.653] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:32:0)
[17:14:17.689] Build status: STARTED
[17:14:17.689] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:33:0) after 1m19s
[17:15:36.753] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:33:0)
[17:15:36.778] Build status: STARTED
[17:15:36.778] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:34:0) after 3m39s
[17:19:15.834] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:34:0)
[17:19:15.851] Build status: STARTED
[17:19:15.851] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:35:0) after 6m34s
[17:25:49.825] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:35:0)
[17:25:49.840] Build status: STARTED
[17:25:49.840] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:36:0) after 4m9s
[17:29:58.840] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:36:0)
[17:29:58.857] Build status: STARTED
[17:29:58.857] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:37:0) after 9m5s
[17:39:03.966] Handling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:37:0)
[17:39:04.161] Build status: STARTED
[17:39:04.161] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win-arm64-rel:8866274080333782512:38:0) after 5m8s
[17:42:58.605] Received PubSub notification, asking Buildbucket for the build status
[17:42:58.621] Build:
{
  "id": "8700844018305268977",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win-arm64-rel"
  },
  "number": 768,
  "createdBy": "project:chromium-m140",
  "createTime": "2025-10-16T14:39:10.893374936Z",
  "startTime": "2025-10-16T14:55:04.112028720Z",
  "endTime": "2025-10-16T17:42:57.757502191Z",
  "updateTime": "2025-10-16T17:42:57.757502191Z",
  "status": "SUCCESS",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "f38463fd645d12a2eb07cd4dae77afabf2ba4139",
      "ref": "refs/branch-heads/7339"
    }
  }
}
[17:42:58.621] Invocation finished in 3h3m49.046084808s with status SUCCEEDED