[04:00:27.109] New invocation is queued and will start shortly
[04:00:28.199] Starting the invocation (attempt 1)
[04:00:28.225] Popped buildset tag "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/136b06634da0a5634978d25769411cc21dd2b7b6"
[04:00:28.225] Popped gitiles commit info from properties and tags
[04:00:28.225] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[04:00:28.226] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[04:00:28.226] Buildbucket request:
{
  "requestId": "8865227100763880272",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win32-official"
  },
  "properties": {
      "$recipe_engine/scheduler": {
            "hostname": "luci-scheduler.appspot.com",
            "invocation": "8865227100763880272",
            "job": "chromium-m140/win32-official",
            "triggers": [
                  {
                        "gitiles": {
                              "ref": "refs/branch-heads/7339",
                              "repo": "https://chromium.googlesource.com/chromium/src",
                              "revision": "136b06634da0a5634978d25769411cc21dd2b7b6"
                            },
                        "id": "https://chromium.googlesource.com/chromium/src/+/refs/branch-heads/7339@136b06634da0a5634978d25769411cc21dd2b7b6",
                        "title": "136b06634da0a5634978d25769411cc21dd2b7b6",
                        "url": "https://chromium.googlesource.com/chromium/src/+/136b06634da0a5634978d25769411cc21dd2b7b6"
                      }
                ]
          }
    },
  "gitilesCommit": {
    "host": "chromium.googlesource.com",
    "project": "chromium/src",
    "id": "136b06634da0a5634978d25769411cc21dd2b7b6",
    "ref": "refs/branch-heads/7339"
  },
  "tags": [
    {
      "key": "scheduler_invocation_id",
      "value": "8865227100763880272"
    },
    {
      "key": "scheduler_job_id",
      "value": "chromium-m140/win32-official"
    },
    {
      "key": "user_agent",
      "value": "luci-scheduler"
    }
  ],
  "notify": {
    "pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
  }
}
[04:00:28.784] Scheduled build:
{
  "id": "8699797038861803137",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win32-official"
  },
  "number": 472,
  "createdBy": "project:chromium-m140",
  "createTime": "2025-10-28T04:00:28.298919526Z",
  "updateTime": "2025-10-28T04:00:28.298919526Z",
  "status": "SCHEDULED",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "136b06634da0a5634978d25769411cc21dd2b7b6",
      "ref": "refs/branch-heads/7339"
    }
  }
}
[04:00:28.784] Task URL: https://cr-buildbucket.appspot.com/build/8699797038861803137
[04:00:28.784] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:2:0) after 5m21s
[04:00:32.452] Received PubSub notification, asking Buildbucket for the build status
[04:00:32.474] Build status: SCHEDULED
[04:00:36.957] Received PubSub notification, asking Buildbucket for the build status
[04:00:36.986] Build status: STARTED
[04:05:49.891] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:2:0)
[04:05:49.909] Build status: STARTED
[04:05:49.909] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:5:0) after 5m39s
[04:11:29.064] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:5:0)
[04:11:29.089] Build status: STARTED
[04:11:29.089] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:6:0) after 3m28s
[04:14:57.119] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:6:0)
[04:14:57.133] Build status: STARTED
[04:14:57.133] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:7:0) after 6m30s
[04:21:27.343] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:7:0)
[04:21:27.366] Build status: STARTED
[04:21:27.366] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:8:0) after 1m29s
[04:22:56.552] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:8:0)
[04:22:56.577] Build status: STARTED
[04:22:56.577] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:9:0) after 3m4s
[04:26:00.682] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:9:0)
[04:26:00.751] Build status: STARTED
[04:26:00.751] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:10:0) after 3m1s
[04:29:01.803] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:10:0)
[04:29:01.822] Build status: STARTED
[04:29:01.822] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:11:0) after 2m52s
[04:31:53.935] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:11:0)
[04:31:54.017] Build status: STARTED
[04:31:54.017] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:12:0) after 6m12s
[04:38:06.033] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:12:0)
[04:38:06.100] Build status: STARTED
[04:38:06.100] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:13:0) after 4m33s
[04:42:39.110] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:13:0)
[04:42:39.125] Build status: STARTED
[04:42:39.125] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:14:0) after 3m49s
[04:46:28.157] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:14:0)
[04:46:28.193] Build status: STARTED
[04:46:28.194] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:15:0) after 2m17s
[04:48:45.240] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:15:0)
[04:48:45.311] Build status: STARTED
[04:48:45.311] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:16:0) after 4m25s
[04:53:10.375] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:16:0)
[04:53:10.402] Build status: STARTED
[04:53:10.402] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:17:0) after 1m58s
[04:55:08.415] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:17:0)
[04:55:08.483] Build status: STARTED
[04:55:08.483] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:18:0) after 3m3s
[04:58:11.494] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:18:0)
[04:58:11.548] Build status: STARTED
[04:58:11.548] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:19:0) after 1m3s
[04:59:14.563] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:19:0)
[04:59:14.618] Build status: STARTED
[04:59:14.618] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:20:0) after 5m47s
[05:05:01.643] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:20:0)
[05:05:01.715] Build status: STARTED
[05:05:01.715] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:21:0) after 3m49s
[05:08:50.726] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:21:0)
[05:08:50.742] Build status: STARTED
[05:08:50.742] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:22:0) after 9m24s
[05:18:14.800] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:22:0)
[05:18:14.817] Build status: STARTED
[05:18:14.817] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:23:0) after 9m18s
[05:27:32.831] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:23:0)
[05:27:32.897] Build status: STARTED
[05:27:32.897] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:24:0) after 3m59s
[05:31:31.871] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:24:0)
[05:31:31.886] Build status: STARTED
[05:31:31.886] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:25:0) after 5m57s
[05:37:28.950] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:25:0)
[05:37:28.966] Build status: STARTED
[05:37:28.967] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:26:0) after 9m34s
[05:47:02.984] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:26:0)
[05:47:03.008] Build status: STARTED
[05:47:03.008] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:27:0) after 9m50s
[05:56:53.126] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:27:0)
[05:56:53.141] Build status: STARTED
[05:56:53.141] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:28:0) after 2m37s
[05:59:30.240] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:28:0)
[05:59:30.256] Build status: STARTED
[05:59:30.256] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:29:0) after 5m34s
[06:05:04.269] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:29:0)
[06:05:04.291] Build status: STARTED
[06:05:04.291] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:30:0) after 3m13s
[06:08:17.388] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:30:0)
[06:08:17.424] Build status: STARTED
[06:08:17.424] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:31:0) after 2m58s
[06:11:15.493] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:31:0)
[06:11:15.521] Build status: STARTED
[06:11:15.521] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:32:0) after 6m22s
[06:17:37.586] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:32:0)
[06:17:37.627] Build status: STARTED
[06:17:37.627] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:33:0) after 8m42s
[06:26:19.668] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:33:0)
[06:26:19.698] Build status: STARTED
[06:26:19.698] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:34:0) after 6m16s
[06:32:35.714] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:34:0)
[06:32:35.800] Build status: STARTED
[06:32:35.800] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:35:0) after 6m0s
[06:38:35.814] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:35:0)
[06:38:35.832] Build status: STARTED
[06:38:35.832] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:36:0) after 4m13s
[06:42:48.909] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:36:0)
[06:42:48.936] Build status: STARTED
[06:42:48.936] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:37:0) after 3m4s
[06:45:53.070] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:37:0)
[06:45:53.090] Build status: STARTED
[06:45:53.090] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:38:0) after 3m35s
[06:49:28.158] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:38:0)
[06:49:28.175] Build status: STARTED
[06:49:28.175] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:39:0) after 1m59s
[06:51:27.152] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:39:0)
[06:51:27.179] Build status: STARTED
[06:51:27.179] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:40:0) after 4m42s
[06:56:09.199] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:40:0)
[06:56:09.347] Build status: STARTED
[06:56:09.347] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:41:0) after 9m4s
[07:05:13.322] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:41:0)
[07:05:13.379] Build status: STARTED
[07:05:13.379] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:42:0) after 3m18s
[07:08:31.413] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:42:0)
[07:08:31.440] Build status: STARTED
[07:08:31.440] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:43:0) after 8m24s
[07:16:55.465] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:43:0)
[07:16:55.514] Build status: STARTED
[07:16:55.514] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:44:0) after 6m48s
[07:23:43.543] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:44:0)
[07:23:43.563] Build status: STARTED
[07:23:43.563] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8865227100763880272:45:0) after 1m48s
[07:24:21.532] Received PubSub notification, asking Buildbucket for the build status
[07:24:21.549] Build:
{
  "id": "8699797038861803137",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win32-official"
  },
  "number": 472,
  "createdBy": "project:chromium-m140",
  "createTime": "2025-10-28T04:00:28.298919526Z",
  "startTime": "2025-10-28T04:00:32.889591247Z",
  "endTime": "2025-10-28T07:24:21.067428082Z",
  "updateTime": "2025-10-28T07:24:21.067428082Z",
  "status": "SUCCESS",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "136b06634da0a5634978d25769411cc21dd2b7b6",
      "ref": "refs/branch-heads/7339"
    }
  }
}
[07:24:21.549] Invocation finished in 3h23m54.449075633s with status SUCCEEDED