[14:33:41.526] New invocation is queued and will start shortly
[14:33:43.011] Starting the invocation (attempt 1)
[14:33:43.037] Popped buildset tag "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/cd690f6d4692a44c38666831793b36a0c2fac050"
[14:33:43.037] Popped gitiles commit info from properties and tags
[14:33:43.038] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[14:33:43.038] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[14:33:43.038] Buildbucket request:
{
  "requestId": "8866365021293985488",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win32-official"
  },
  "properties": {
      "$recipe_engine/scheduler": {
            "hostname": "luci-scheduler.appspot.com",
            "invocation": "8866365021293985488",
            "job": "chromium-m140/win32-official",
            "triggers": [
                  {
                        "gitiles": {
                              "ref": "refs/branch-heads/7339",
                              "repo": "https://chromium.googlesource.com/chromium/src",
                              "revision": "cd690f6d4692a44c38666831793b36a0c2fac050"
                            },
                        "id": "https://chromium.googlesource.com/chromium/src/+/refs/branch-heads/7339@cd690f6d4692a44c38666831793b36a0c2fac050",
                        "title": "cd690f6d4692a44c38666831793b36a0c2fac050",
                        "url": "https://chromium.googlesource.com/chromium/src/+/cd690f6d4692a44c38666831793b36a0c2fac050"
                      }
                ]
          }
    },
  "gitilesCommit": {
    "host": "chromium.googlesource.com",
    "project": "chromium/src",
    "id": "cd690f6d4692a44c38666831793b36a0c2fac050",
    "ref": "refs/branch-heads/7339"
  },
  "tags": [
    {
      "key": "scheduler_invocation_id",
      "value": "8866365021293985488"
    },
    {
      "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"
  }
}
[14:33:43.576] Scheduled build:
{
  "id": "8700934958991991761",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win32-official"
  },
  "number": 443,
  "createdBy": "project:chromium-m140",
  "createTime": "2025-10-15T14:33:43.096302435Z",
  "updateTime": "2025-10-15T14:33:43.096302435Z",
  "status": "SCHEDULED",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "cd690f6d4692a44c38666831793b36a0c2fac050",
      "ref": "refs/branch-heads/7339"
    }
  }
}
[14:33:43.576] Task URL: https://cr-buildbucket.appspot.com/build/8700934958991991761
[14:33:43.576] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:2:0) after 2m1s
[14:33:44.575] Received PubSub notification, asking Buildbucket for the build status
[14:33:44.590] Build status: SCHEDULED
[14:33:48.079] Received PubSub notification, asking Buildbucket for the build status
[14:33:48.098] Build status: STARTED
[14:35:44.812] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:2:0)
[14:35:44.852] Build status: STARTED
[14:35:44.853] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:5:0) after 6m5s
[14:41:49.937] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:5:0)
[14:41:49.957] Build status: STARTED
[14:41:49.957] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:6:0) after 1m10s
[14:43:00.021] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:6:0)
[14:43:00.048] Build status: STARTED
[14:43:00.049] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:7:0) after 5m44s
[14:48:44.112] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:7:0)
[14:48:44.131] Build status: STARTED
[14:48:44.131] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:8:0) after 3m56s
[14:52:40.167] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:8:0)
[14:52:40.202] Build status: STARTED
[14:52:40.202] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:9:0) after 9m45s
[15:02:25.236] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:9:0)
[15:02:25.266] Build status: STARTED
[15:02:25.266] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:10:0) after 9m24s
[15:11:49.279] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:10:0)
[15:11:49.307] Build status: STARTED
[15:11:49.307] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:11:0) after 2m59s
[15:14:48.320] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:11:0)
[15:14:48.344] Build status: STARTED
[15:14:48.344] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:12:0) after 3m5s
[15:17:53.404] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:12:0)
[15:17:53.426] Build status: STARTED
[15:17:53.426] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:13:0) after 8m49s
[15:26:42.490] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:13:0)
[15:26:42.507] Build status: STARTED
[15:26:42.507] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:14:0) after 1m24s
[15:28:06.522] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:14:0)
[15:28:06.538] Build status: STARTED
[15:28:06.538] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:15:0) after 9m29s
[15:37:35.554] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:15:0)
[15:37:35.575] Build status: STARTED
[15:37:35.575] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:16:0) after 5m50s
[15:43:25.638] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:16:0)
[15:43:25.655] Build status: STARTED
[15:43:25.655] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:17:0) after 9m19s
[15:52:44.650] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:17:0)
[15:52:44.668] Build status: STARTED
[15:52:44.668] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:18:0) after 3m34s
[15:56:18.683] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:18:0)
[15:56:18.715] Build status: STARTED
[15:56:18.715] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:19:0) after 5m19s
[16:01:37.711] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:19:0)
[16:01:37.746] Build status: STARTED
[16:01:37.746] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:20:0) after 1m54s
[16:03:31.814] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:20:0)
[16:03:31.828] Build status: STARTED
[16:03:31.828] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:21:0) after 8m7s
[16:11:38.862] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:21:0)
[16:11:38.898] Build status: STARTED
[16:11:38.898] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:22:0) after 3m25s
[16:15:03.962] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:22:0)
[16:15:04.015] Build status: STARTED
[16:15:04.015] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:23:0) after 4m2s
[16:19:06.021] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:23:0)
[16:19:06.043] Build status: STARTED
[16:19:06.043] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:24:0) after 2m32s
[16:21:38.098] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:24:0)
[16:21:38.113] Build status: STARTED
[16:21:38.113] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:25:0) after 1m10s
[16:22:48.129] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:25:0)
[16:22:48.159] Build status: STARTED
[16:22:48.159] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:26:0) after 6m39s
[16:29:27.175] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:26:0)
[16:29:27.256] Build status: STARTED
[16:29:27.256] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:27:0) after 4m50s
[16:34:17.270] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:27:0)
[16:34:17.287] Build status: STARTED
[16:34:17.288] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:28:0) after 5m45s
[16:40:02.486] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:28:0)
[16:40:02.509] Build status: STARTED
[16:40:02.509] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:29:0) after 9m28s
[16:49:30.572] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:29:0)
[16:49:30.588] Build status: STARTED
[16:49:30.588] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:30:0) after 7m25s
[16:56:55.807] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:30:0)
[16:56:55.825] Build status: STARTED
[16:56:55.825] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:31:0) after 8m53s
[17:05:48.887] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:31:0)
[17:05:48.904] Build status: STARTED
[17:05:48.905] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:32:0) after 5m22s
[17:11:10.966] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:32:0)
[17:11:13.636] Build status: STARTED
[17:11:13.636] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:33:0) after 8m59s
[17:20:12.651] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:33:0)
[17:20:12.671] Build status: STARTED
[17:20:12.671] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:34:0) after 8m18s
[17:28:30.684] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:34:0)
[17:28:30.706] Build status: STARTED
[17:28:30.706] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:35:0) after 7m19s
[17:35:49.849] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:35:0)
[17:35:49.906] Build status: STARTED
[17:35:49.906] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:36:0) after 7m15s
[17:43:04.972] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:36:0)
[17:43:04.985] Build status: STARTED
[17:43:04.985] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:37:0) after 8m16s
[17:51:20.997] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:37:0)
[17:51:21.100] Build status: STARTED
[17:51:21.100] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:38:0) after 8m41s
[18:00:02.113] Handling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:38:0)
[18:00:02.186] Build status: STARTED
[18:00:02.186] Scheduling timer "check-buildbucket-build-status" (chromium-m140/win32-official:8866365021293985488:39:0) after 4m22s
[18:00:27.265] Received PubSub notification, asking Buildbucket for the build status
[18:00:27.288] Build:
{
  "id": "8700934958991991761",
  "builder": {
    "project": "chromium-m140",
    "bucket": "ci",
    "builder": "win32-official"
  },
  "number": 443,
  "createdBy": "project:chromium-m140",
  "createTime": "2025-10-15T14:33:43.096302435Z",
  "startTime": "2025-10-15T14:33:47.879426893Z",
  "endTime": "2025-10-15T18:00:26.648326550Z",
  "updateTime": "2025-10-15T18:00:26.648326550Z",
  "status": "SUCCESS",
  "input": {
    "gitilesCommit": {
      "host": "chromium.googlesource.com",
      "project": "chromium/src",
      "id": "cd690f6d4692a44c38666831793b36a0c2fac050",
      "ref": "refs/branch-heads/7339"
    }
  }
}
[18:00:27.288] Invocation finished in 3h26m45.770531948s with status SUCCEEDED