[17:04:49.762] New invocation is queued and will start shortly
[17:04:52.157] Starting the invocation (attempt 1)
[17:04:52.197] Popped buildset tag "buildset:commit/gitiles/chromium.googlesource.com/native_client/src/native_client/+/9deae6223a807d17f4d06a1a0cfee2abe3327227"
[17:04:52.197] Popped gitiles commit info from properties and tags
[17:04:52.197] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[17:04:52.197] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[17:04:52.198] Buildbucket request:
{
"requestId": "8995184398786746576",
"builder": {
"project": "nacl",
"bucket": "toolchain",
"builder": "linux-pnacl-x86_64"
},
"properties": {
"$recipe_engine/scheduler": {
"hostname": "luci-scheduler.appspot.com",
"triggers": [
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://chromium.googlesource.com/native_client/src/native_client",
"revision": "9deae6223a807d17f4d06a1a0cfee2abe3327227"
},
"id": "https://chromium.googlesource.com/native_client/src/native_client/+/refs/heads/main@9deae6223a807d17f4d06a1a0cfee2abe3327227",
"title": "9deae6223a807d17f4d06a1a0cfee2abe3327227",
"url": "https://chromium.googlesource.com/native_client/src/native_client/+/9deae6223a807d17f4d06a1a0cfee2abe3327227"
}
]
}
},
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "native_client/src/native_client",
"id": "9deae6223a807d17f4d06a1a0cfee2abe3327227",
"ref": "refs/heads/main"
},
"tags": [
{
"key": "scheduler_invocation_id",
"value": "8995184398786746576"
},
{
"key": "scheduler_job_id",
"value": "nacl/linux-pnacl-x86_64"
},
{
"key": "user_agent",
"value": "luci-scheduler"
}
],
"notify": {
"pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
}
}
[17:04:52.661] Scheduled build:
{
"id": "8829754335507495233",
"builder": {
"project": "nacl",
"bucket": "toolchain",
"builder": "linux-pnacl-x86_64"
},
"number": 7184,
"createdBy": "project:nacl",
"createTime": "2021-11-23T17:04:52.257179059Z",
"updateTime": "2021-11-23T17:04:52.257179059Z",
"status": "SCHEDULED",
"input": {
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "native_client/src/native_client",
"id": "9deae6223a807d17f4d06a1a0cfee2abe3327227",
"ref": "refs/heads/main"
}
}
}
[17:04:52.661] Task URL: https://cr-buildbucket.appspot.com/build/8829754335507495233
[17:04:52.661] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:2:0) after 4m38s
[17:09:30.734] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:2:0)
[17:09:30.814] Build status: SCHEDULED
[17:09:30.814] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:3:0) after 9m23s
[17:18:53.921] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:3:0)
[17:18:53.972] Build status: SCHEDULED
[17:18:53.972] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:4:0) after 6m23s
[17:25:17.048] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:4:0)
[17:25:17.090] Build status: SCHEDULED
[17:25:17.090] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:5:0) after 4m46s
[17:30:03.117] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:5:0)
[17:30:03.170] Build status: SCHEDULED
[17:30:03.170] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:6:0) after 5m22s
[17:35:25.194] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:6:0)
[17:35:25.221] Build status: SCHEDULED
[17:35:25.221] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:7:0) after 6m53s
[17:42:18.236] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:7:0)
[17:42:18.268] Build status: SCHEDULED
[17:42:18.268] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:8:0) after 3m12s
[17:45:30.337] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:8:0)
[17:45:30.360] Build status: SCHEDULED
[17:45:30.360] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:9:0) after 7m42s
[17:53:12.780] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:9:0)
[17:53:12.808] Build status: SCHEDULED
[17:53:12.808] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:10:0) after 1m33s
[17:54:45.844] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:10:0)
[17:54:45.875] Build status: SCHEDULED
[17:54:45.875] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:11:0) after 6m41s
[18:01:26.894] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:11:0)
[18:01:26.927] Build status: SCHEDULED
[18:01:26.927] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:12:0) after 6m53s
[18:08:19.999] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:12:0)
[18:08:20.029] Build status: SCHEDULED
[18:08:20.029] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:13:0) after 6m34s
[18:14:54.146] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:13:0)
[18:14:54.188] Build status: SCHEDULED
[18:14:54.188] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:14:0) after 9m56s
[18:24:50.461] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:14:0)
[18:24:50.489] Build status: SCHEDULED
[18:24:50.489] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:15:0) after 3m15s
[18:28:05.871] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:15:0)
[18:28:05.975] Build status: SCHEDULED
[18:28:05.975] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:16:0) after 4m35s
[18:32:41.135] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:16:0)
[18:32:41.165] Build status: SCHEDULED
[18:32:41.165] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:17:0) after 8m51s
[18:41:32.266] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:17:0)
[18:41:32.393] Build status: SCHEDULED
[18:41:32.393] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:18:0) after 8m19s
[18:49:51.409] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:18:0)
[18:49:51.450] Build status: SCHEDULED
[18:49:51.450] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:19:0) after 7m42s
[18:53:09.980] Received PubSub notification, asking Buildbucket for the build status
[18:53:10.034] Build status: STARTED
[18:57:33.480] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:19:0)
[18:57:33.531] Build status: STARTED
[18:57:33.531] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:21:0) after 7m47s
[19:05:21.131] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:21:0)
[19:05:21.211] Build status: STARTED
[19:05:21.211] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:22:0) after 3m15s
[19:08:36.840] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:22:0)
[19:08:36.876] Build status: STARTED
[19:08:36.876] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:23:0) after 9m9s
[19:17:46.047] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:23:0)
[19:17:46.085] Build status: STARTED
[19:17:46.085] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:24:0) after 5m11s
[19:22:57.250] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:24:0)
[19:22:57.307] Build status: STARTED
[19:22:57.307] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:25:0) after 6m19s
[19:29:16.326] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:25:0)
[19:29:16.363] Build status: STARTED
[19:29:16.363] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:26:0) after 7m43s
[19:36:59.582] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:26:0)
[19:36:59.623] Build status: STARTED
[19:36:59.623] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:27:0) after 4m22s
[19:41:21.858] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:27:0)
[19:41:21.889] Build status: STARTED
[19:41:21.889] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:28:0) after 8m25s
[19:49:47.169] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:28:0)
[19:49:47.236] Build status: STARTED
[19:49:47.236] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:29:0) after 2m9s
[19:51:56.466] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:29:0)
[19:51:56.518] Build status: STARTED
[19:51:56.518] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:30:0) after 6m36s
[19:58:32.959] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:30:0)
[19:58:33.003] Build status: STARTED
[19:58:33.003] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:31:0) after 9m9s
[20:07:42.132] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:31:0)
[20:07:42.165] Build status: STARTED
[20:07:42.165] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:32:0) after 8m40s
[20:16:22.174] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:32:0)
[20:16:22.218] Build status: STARTED
[20:16:22.218] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:33:0) after 4m0s
[20:20:22.386] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:33:0)
[20:20:22.418] Build status: STARTED
[20:20:22.418] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:34:0) after 6m33s
[20:26:55.696] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:34:0)
[20:26:55.767] Build status: STARTED
[20:26:55.767] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:35:0) after 6m20s
[20:33:15.855] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:35:0)
[20:33:15.893] Build status: STARTED
[20:33:15.893] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:36:0) after 1m30s
[20:34:45.960] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:36:0)
[20:34:46.005] Build status: STARTED
[20:34:46.006] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:37:0) after 4m38s
[20:39:24.451] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:37:0)
[20:39:24.488] Build status: STARTED
[20:39:24.488] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:38:0) after 1m40s
[20:41:04.647] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:38:0)
[20:41:04.688] Build status: STARTED
[20:41:04.688] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:39:0) after 7m20s
[20:48:25.017] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:39:0)
[20:48:25.075] Build status: STARTED
[20:48:25.075] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:40:0) after 5m51s
[20:54:16.170] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:40:0)
[20:54:16.207] Build status: STARTED
[20:54:16.207] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:41:0) after 5m31s
[20:59:47.225] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:41:0)
[20:59:47.255] Build status: STARTED
[20:59:47.255] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:42:0) after 4m6s
[21:03:53.272] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:42:0)
[21:03:53.312] Build status: STARTED
[21:03:53.312] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:43:0) after 1m37s
[21:05:30.506] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:43:0)
[21:05:30.543] Build status: STARTED
[21:05:30.543] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:44:0) after 9m23s
[21:14:53.566] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:44:0)
[21:14:53.595] Build status: STARTED
[21:14:53.595] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:45:0) after 4m32s
[21:19:25.627] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:45:0)
[21:19:25.705] Build status: STARTED
[21:19:25.705] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:46:0) after 7m21s
[21:26:46.764] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:46:0)
[21:26:46.800] Build status: STARTED
[21:26:46.800] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:47:0) after 1m45s
[21:28:32.006] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:47:0)
[21:28:32.039] Build status: STARTED
[21:28:32.039] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:48:0) after 6m26s
[21:34:58.160] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:48:0)
[21:34:58.199] Build status: STARTED
[21:34:58.199] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:49:0) after 2m4s
[21:37:02.228] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:49:0)
[21:37:02.263] Build status: STARTED
[21:37:02.263] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:50:0) after 9m33s
[21:46:35.289] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:50:0)
[21:46:35.329] Build status: STARTED
[21:46:35.329] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:51:0) after 3m13s
[21:49:48.436] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:51:0)
[21:49:48.474] Build status: STARTED
[21:49:48.474] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:52:0) after 6m6s
[21:55:54.490] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:52:0)
[21:55:54.530] Build status: STARTED
[21:55:54.530] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:53:0) after 7m56s
[22:03:50.546] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:53:0)
[22:03:50.583] Build status: STARTED
[22:03:50.583] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:54:0) after 7m49s
[22:11:39.708] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:54:0)
[22:11:39.746] Build status: STARTED
[22:11:39.746] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:55:0) after 4m57s
[22:16:37.133] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:55:0)
[22:16:37.165] Build status: STARTED
[22:16:37.165] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64:8995184398786746576:56:0) after 8m59s
[22:17:21.108] Received PubSub notification, asking Buildbucket for the build status
[22:17:21.190] Build:
{
"id": "8829754335507495233",
"builder": {
"project": "nacl",
"bucket": "toolchain",
"builder": "linux-pnacl-x86_64"
},
"number": 7184,
"createdBy": "project:nacl",
"createTime": "2021-11-23T17:04:52.257179059Z",
"startTime": "2021-11-23T18:53:08.884340Z",
"endTime": "2021-11-23T22:17:19.181094Z",
"updateTime": "2021-11-23T22:17:19.912915Z",
"status": "SUCCESS",
"input": {
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "native_client/src/native_client",
"id": "9deae6223a807d17f4d06a1a0cfee2abe3327227",
"ref": "refs/heads/main"
}
}
}
[22:17:21.190] Invocation finished in 5h12m31.444613363s with status SUCCEEDED