[19:38:54.049] New invocation is queued and will start shortly
[19:38:55.121] Starting the invocation (attempt 1)
[19:38:55.158] Popped buildset tag "buildset:commit/gitiles/chromium.googlesource.com/infra/infra/+/e92cab4ff3798e75fad7b829023f2baa4fe83c91"
[19:38:55.158] Popped gitiles commit info from properties and tags
[19:38:55.158] Preparing PubSub topic for "https://cr-buildbucket-dev.appspot.com"
[19:38:55.159] PubSub topic is "projects/luci-scheduler-dev/topics/scheduler.buildbucket.cr-buildbucket-dev~appspot.gserviceaccount.com"
[19:38:55.159] Buildbucket request:
{
"requestId": "8975243372842402160",
"builder": {
"project": "infra",
"bucket": "ci",
"builder": "infra-continuous-win10-64"
},
"properties": {
"$recipe_engine/scheduler": {
"hostname": "luci-scheduler-dev.appspot.com",
"invocation": "8975243372842402160",
"job": "infra/infra-continuous-win10-64",
"triggers": [
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "4597f7c9f89c9c04b09af64b5d1b6aa1957c023e"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@4597f7c9f89c9c04b09af64b5d1b6aa1957c023e",
"title": "4597f7c9f89c9c04b09af64b5d1b6aa1957c023e",
"url": "https://chromium.googlesource.com/infra/infra/+/4597f7c9f89c9c04b09af64b5d1b6aa1957c023e"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "ea40b37d9506723d7deeb8c431fb38cb44eb3306"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@ea40b37d9506723d7deeb8c431fb38cb44eb3306",
"title": "ea40b37d9506723d7deeb8c431fb38cb44eb3306",
"url": "https://chromium.googlesource.com/infra/infra/+/ea40b37d9506723d7deeb8c431fb38cb44eb3306"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "fa2a351b6470b922be414e5ea1efe390481400aa"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@fa2a351b6470b922be414e5ea1efe390481400aa",
"title": "fa2a351b6470b922be414e5ea1efe390481400aa",
"url": "https://chromium.googlesource.com/infra/infra/+/fa2a351b6470b922be414e5ea1efe390481400aa"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "43e1ec5e2001ba04dc2b1bfdf409a14aed6ff721"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@43e1ec5e2001ba04dc2b1bfdf409a14aed6ff721",
"title": "43e1ec5e2001ba04dc2b1bfdf409a14aed6ff721",
"url": "https://chromium.googlesource.com/infra/infra/+/43e1ec5e2001ba04dc2b1bfdf409a14aed6ff721"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "b202ad42f4b072b6a90fb7ab1714bb357f519118"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@b202ad42f4b072b6a90fb7ab1714bb357f519118",
"title": "b202ad42f4b072b6a90fb7ab1714bb357f519118",
"url": "https://chromium.googlesource.com/infra/infra/+/b202ad42f4b072b6a90fb7ab1714bb357f519118"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "1bb5b1f0727782b355f53fff4cd9e901d3942bbb"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@1bb5b1f0727782b355f53fff4cd9e901d3942bbb",
"title": "1bb5b1f0727782b355f53fff4cd9e901d3942bbb",
"url": "https://chromium.googlesource.com/infra/infra/+/1bb5b1f0727782b355f53fff4cd9e901d3942bbb"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "4faf84686ffa294653b37f4466ab36c94dadc597"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@4faf84686ffa294653b37f4466ab36c94dadc597",
"title": "4faf84686ffa294653b37f4466ab36c94dadc597",
"url": "https://chromium.googlesource.com/infra/infra/+/4faf84686ffa294653b37f4466ab36c94dadc597"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "c5d6543663d2e956c34d2d9a7a24dba94f4e7c44"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@c5d6543663d2e956c34d2d9a7a24dba94f4e7c44",
"title": "c5d6543663d2e956c34d2d9a7a24dba94f4e7c44",
"url": "https://chromium.googlesource.com/infra/infra/+/c5d6543663d2e956c34d2d9a7a24dba94f4e7c44"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "f1a9d718cfd6649be7e714cab56f5f82dc6cea20"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@f1a9d718cfd6649be7e714cab56f5f82dc6cea20",
"title": "f1a9d718cfd6649be7e714cab56f5f82dc6cea20",
"url": "https://chromium.googlesource.com/infra/infra/+/f1a9d718cfd6649be7e714cab56f5f82dc6cea20"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "7cf88d0be64a19fa656b443adcb6f57a4ea85663"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@7cf88d0be64a19fa656b443adcb6f57a4ea85663",
"title": "7cf88d0be64a19fa656b443adcb6f57a4ea85663",
"url": "https://chromium.googlesource.com/infra/infra/+/7cf88d0be64a19fa656b443adcb6f57a4ea85663"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "0b6ec97b22b4878a10257c976b9e5e37eae3c9cc"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@0b6ec97b22b4878a10257c976b9e5e37eae3c9cc",
"title": "0b6ec97b22b4878a10257c976b9e5e37eae3c9cc",
"url": "https://chromium.googlesource.com/infra/infra/+/0b6ec97b22b4878a10257c976b9e5e37eae3c9cc"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "1f490479a93b5b9fcafe0bc6ba2ff9fc5950ee45"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@1f490479a93b5b9fcafe0bc6ba2ff9fc5950ee45",
"title": "1f490479a93b5b9fcafe0bc6ba2ff9fc5950ee45",
"url": "https://chromium.googlesource.com/infra/infra/+/1f490479a93b5b9fcafe0bc6ba2ff9fc5950ee45"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "55594c4f6f68de6f0f610cb9fae5b9f8bc555a57"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@55594c4f6f68de6f0f610cb9fae5b9f8bc555a57",
"title": "55594c4f6f68de6f0f610cb9fae5b9f8bc555a57",
"url": "https://chromium.googlesource.com/infra/infra/+/55594c4f6f68de6f0f610cb9fae5b9f8bc555a57"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "9ef59fdb9e2baa786908795f8e50408fa09ad596"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@9ef59fdb9e2baa786908795f8e50408fa09ad596",
"title": "9ef59fdb9e2baa786908795f8e50408fa09ad596",
"url": "https://chromium.googlesource.com/infra/infra/+/9ef59fdb9e2baa786908795f8e50408fa09ad596"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "e92cab4ff3798e75fad7b829023f2baa4fe83c91"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/main@e92cab4ff3798e75fad7b829023f2baa4fe83c91",
"title": "e92cab4ff3798e75fad7b829023f2baa4fe83c91",
"url": "https://chromium.googlesource.com/infra/infra/+/e92cab4ff3798e75fad7b829023f2baa4fe83c91"
}
]
}
},
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "infra/infra",
"id": "e92cab4ff3798e75fad7b829023f2baa4fe83c91",
"ref": "refs/heads/main"
},
"tags": [
{
"key": "scheduler_invocation_id",
"value": "8975243372842402160"
},
{
"key": "scheduler_job_id",
"value": "infra/infra-continuous-win10-64"
},
{
"key": "user_agent",
"value": "luci-scheduler-dev"
}
],
"notify": {
"pubsubTopic": "projects/luci-scheduler-dev/topics/scheduler.buildbucket.cr-buildbucket-dev~appspot.gserviceaccount.com"
}
}
[19:38:56.115] Scheduled build:
{
"id": "8809813310945720897",
"builder": {
"project": "infra",
"bucket": "ci",
"builder": "infra-continuous-win10-64"
},
"number": 22833,
"createdBy": "project:infra",
"createTime": "2022-07-01T19:38:55.225397894Z",
"updateTime": "2022-07-01T19:38:55.225397894Z",
"status": "SCHEDULED",
"input": {
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "infra/infra",
"id": "e92cab4ff3798e75fad7b829023f2baa4fe83c91",
"ref": "refs/heads/main"
}
},
"canary": true
}
[19:38:56.115] Task URL: https://cr-buildbucket-dev.appspot.com/build/8809813310945720897
[19:38:56.115] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:2:0) after 7m21s
[19:46:17.139] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:2:0)
[19:46:17.174] Build status: SCHEDULED
[19:46:17.174] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:3:0) after 5m7s
[19:51:24.204] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:3:0)
[19:51:24.293] Build status: SCHEDULED
[19:51:24.293] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:4:0) after 6m30s
[19:57:54.314] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:4:0)
[19:57:54.370] Build status: SCHEDULED
[19:57:54.370] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:5:0) after 6m37s
[20:04:31.391] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:5:0)
[20:04:31.417] Build status: SCHEDULED
[20:04:31.417] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:6:0) after 4m42s
[20:09:14.419] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:6:0)
[20:09:14.451] Build status: SCHEDULED
[20:09:14.451] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:7:0) after 8m53s
[20:18:07.475] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:7:0)
[20:18:07.530] Build status: SCHEDULED
[20:18:07.530] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:8:0) after 4m45s
[20:22:52.558] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:8:0)
[20:22:52.591] Build status: SCHEDULED
[20:22:52.591] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:9:0) after 5m53s
[20:28:45.614] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:9:0)
[20:28:45.663] Build status: SCHEDULED
[20:28:45.663] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:10:0) after 2m6s
[20:30:51.685] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:10:0)
[20:30:51.720] Build status: SCHEDULED
[20:30:51.720] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:11:0) after 3m44s
[20:34:35.757] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:11:0)
[20:34:35.794] Build status: SCHEDULED
[20:34:35.794] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:12:0) after 4m7s
[20:38:42.817] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:12:0)
[20:38:42.894] Build status: SCHEDULED
[20:38:42.894] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:13:0) after 1m44s
[20:40:26.916] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:13:0)
[20:40:26.975] Build status: SCHEDULED
[20:40:26.975] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:14:0) after 3m46s
[20:44:13.001] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:14:0)
[20:44:13.039] Build status: SCHEDULED
[20:44:13.039] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:15:0) after 2m15s
[20:46:28.063] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:15:0)
[20:46:28.802] Build status: SCHEDULED
[20:46:28.802] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:16:0) after 1m29s
[20:47:57.827] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:16:0)
[20:47:57.865] Build status: SCHEDULED
[20:47:57.865] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:17:0) after 1m32s
[20:49:29.885] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:17:0)
[20:49:29.921] Build status: SCHEDULED
[20:49:29.921] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:18:0) after 4m58s
[20:54:27.946] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:18:0)
[20:54:28.010] Build status: SCHEDULED
[20:54:28.010] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:19:0) after 3m22s
[20:57:50.034] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:19:0)
[20:57:50.065] Build status: SCHEDULED
[20:57:50.065] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:20:0) after 4m31s
[21:02:21.091] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:20:0)
[21:02:21.147] Build status: SCHEDULED
[21:02:21.147] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:21:0) after 9m15s
[21:11:36.167] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:21:0)
[21:11:36.227] Build status: SCHEDULED
[21:11:36.227] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:22:0) after 5m36s
[21:17:12.266] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:22:0)
[21:17:12.319] Build status: SCHEDULED
[21:17:12.319] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:23:0) after 4m55s
[21:22:07.341] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:23:0)
[21:22:07.386] Build status: SCHEDULED
[21:22:07.386] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:24:0) after 9m28s
[21:31:35.516] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:24:0)
[21:31:35.579] Build status: SCHEDULED
[21:31:35.579] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:25:0) after 7m19s
[21:38:54.604] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:25:0)
[21:38:54.654] Build status: SCHEDULED
[21:38:54.654] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:26:0) after 5m43s
[21:44:37.677] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:26:0)
[21:44:37.732] Build status: SCHEDULED
[21:44:37.732] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:27:0) after 3m8s
[21:47:45.755] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:27:0)
[21:47:45.781] Build status: SCHEDULED
[21:47:45.781] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:28:0) after 4m21s
[21:52:06.807] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:28:0)
[21:52:06.882] Build status: SCHEDULED
[21:52:06.882] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:29:0) after 6m34s
[21:58:40.911] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:29:0)
[21:58:40.937] Build status: SCHEDULED
[21:58:40.937] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:30:0) after 4m53s
[22:03:33.964] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:30:0)
[22:03:33.987] Build status: SCHEDULED
[22:03:33.988] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:31:0) after 1m9s
[22:04:43.051] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:31:0)
[22:04:43.111] Build status: SCHEDULED
[22:04:43.111] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:32:0) after 1m5s
[22:05:05.344] Received PubSub notification, asking Buildbucket for the build status
[22:05:05.379] Build status: STARTED
[22:05:48.137] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:32:0)
[22:05:48.197] Build status: STARTED
[22:05:48.197] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:34:0) after 6m39s
[22:12:27.224] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:34:0)
[22:12:27.299] Build status: STARTED
[22:12:27.299] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:35:0) after 6m9s
[22:18:36.326] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:35:0)
[22:18:36.368] Build status: STARTED
[22:18:36.368] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:36:0) after 1m40s
[22:20:16.414] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:36:0)
[22:20:16.451] Build status: STARTED
[22:20:16.451] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:8975243372842402160:37:0) after 7m20s
[22:20:58.932] Received PubSub notification, asking Buildbucket for the build status
[22:20:58.995] Build:
{
"id": "8809813310945720897",
"builder": {
"project": "infra",
"bucket": "ci",
"builder": "infra-continuous-win10-64"
},
"number": 22833,
"createdBy": "project:infra",
"createTime": "2022-07-01T19:38:55.225397894Z",
"startTime": "2022-07-01T22:05:02.147793Z",
"endTime": "2022-07-01T22:20:58.493510500Z",
"updateTime": "2022-07-01T22:20:58.493510500Z",
"status": "SUCCESS",
"input": {
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "infra/infra",
"id": "e92cab4ff3798e75fad7b829023f2baa4fe83c91",
"ref": "refs/heads/main"
}
},
"canary": true
}
[22:20:58.995] Invocation finished in 2h42m4.962656095s with status SUCCEEDED