[10:54:07.545] New invocation is queued and will start shortly
[10:54:09.298] Starting the invocation (attempt 1)
[10:54:09.344] Popped buildset tag "buildset:commit/gitiles/r8.googlesource.com/r8/+/29dc783003241692a40c7efd744139a4963fc82d"
[10:54:09.344] Popped gitiles commit info from properties and tags
[10:54:09.344] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[10:54:09.344] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[10:54:09.344] Buildbucket request:
{
"requestId": "8961596246908784976",
"builder": {
"project": "r8",
"bucket": "ci",
"builder": "linux-internal"
},
"properties": {
"$recipe_engine/scheduler": {
"hostname": "luci-scheduler.appspot.com",
"invocation": "8961596246908784976",
"job": "r8/linux-internal",
"triggers": [
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://r8.googlesource.com/r8",
"revision": "bbfb90da625c119563b44eb47fe21a4bdfec4a78"
},
"id": "https://r8.googlesource.com/r8/+/refs/heads/main@bbfb90da625c119563b44eb47fe21a4bdfec4a78",
"title": "bbfb90da625c119563b44eb47fe21a4bdfec4a78",
"url": "https://r8.googlesource.com/r8/+/bbfb90da625c119563b44eb47fe21a4bdfec4a78"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://r8.googlesource.com/r8",
"revision": "c57812e79dabfa3324a93033fa64475437748c6a"
},
"id": "https://r8.googlesource.com/r8/+/refs/heads/main@c57812e79dabfa3324a93033fa64475437748c6a",
"title": "c57812e79dabfa3324a93033fa64475437748c6a",
"url": "https://r8.googlesource.com/r8/+/c57812e79dabfa3324a93033fa64475437748c6a"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://r8.googlesource.com/r8",
"revision": "4e346053460be40df72c58f21d58864a2aaefded"
},
"id": "https://r8.googlesource.com/r8/+/refs/heads/main@4e346053460be40df72c58f21d58864a2aaefded",
"title": "4e346053460be40df72c58f21d58864a2aaefded",
"url": "https://r8.googlesource.com/r8/+/4e346053460be40df72c58f21d58864a2aaefded"
},
{
"gitiles": {
"ref": "refs/heads/main",
"repo": "https://r8.googlesource.com/r8",
"revision": "29dc783003241692a40c7efd744139a4963fc82d"
},
"id": "https://r8.googlesource.com/r8/+/refs/heads/main@29dc783003241692a40c7efd744139a4963fc82d",
"title": "29dc783003241692a40c7efd744139a4963fc82d",
"url": "https://r8.googlesource.com/r8/+/29dc783003241692a40c7efd744139a4963fc82d"
}
]
}
},
"gitilesCommit": {
"host": "r8.googlesource.com",
"project": "r8",
"id": "29dc783003241692a40c7efd744139a4963fc82d",
"ref": "refs/heads/main"
},
"tags": [
{
"key": "scheduler_invocation_id",
"value": "8961596246908784976"
},
{
"key": "scheduler_job_id",
"value": "r8/linux-internal"
},
{
"key": "user_agent",
"value": "luci-scheduler"
}
],
"notify": {
"pubsubTopic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
}
}
[10:54:09.733] Scheduled build:
{
"id": "8796166184283762337",
"builder": {
"project": "r8",
"bucket": "ci",
"builder": "linux-internal"
},
"number": 2889,
"createdBy": "project:r8",
"createTime": "2022-11-29T10:54:09.415142429Z",
"updateTime": "2022-11-29T10:54:09.415142429Z",
"status": "SCHEDULED",
"input": {
"gitilesCommit": {
"host": "r8.googlesource.com",
"project": "r8",
"id": "29dc783003241692a40c7efd744139a4963fc82d",
"ref": "refs/heads/main"
}
},
"canary": true
}
[10:54:09.733] Task URL: https://cr-buildbucket.appspot.com/build/8796166184283762337
[10:54:09.733] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:2:0) after 7m11s
[11:01:20.731] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:2:0)
[11:01:20.759] Build status: SCHEDULED
[11:01:20.759] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:3:0) after 8m25s
[11:09:45.959] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:3:0)
[11:09:45.984] Build status: SCHEDULED
[11:09:45.984] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:4:0) after 5m59s
[11:15:45.159] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:4:0)
[11:15:45.195] Build status: SCHEDULED
[11:15:45.195] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:5:0) after 7m32s
[11:23:17.371] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:5:0)
[11:23:17.391] Build status: SCHEDULED
[11:23:17.391] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:6:0) after 6m11s
[11:29:28.532] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:6:0)
[11:29:28.554] Build status: SCHEDULED
[11:29:28.554] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:7:0) after 2m31s
[11:31:59.716] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:7:0)
[11:31:59.738] Build status: SCHEDULED
[11:31:59.738] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:8:0) after 7m2s
[11:39:01.832] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:8:0)
[11:39:01.879] Build status: SCHEDULED
[11:39:01.879] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:9:0) after 3m45s
[11:42:47.033] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:9:0)
[11:42:47.119] Build status: SCHEDULED
[11:42:47.120] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:10:0) after 3m58s
[11:46:45.244] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:10:0)
[11:46:45.270] Build status: SCHEDULED
[11:46:45.270] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:11:0) after 3m56s
[11:50:41.381] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:11:0)
[11:50:41.402] Build status: SCHEDULED
[11:50:41.402] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:12:0) after 9m36s
[12:00:17.677] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:12:0)
[12:00:17.702] Build status: SCHEDULED
[12:00:17.702] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:13:0) after 5m59s
[12:06:17.022] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:13:0)
[12:06:17.197] Build status: SCHEDULED
[12:06:17.198] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:14:0) after 5m35s
[12:11:52.453] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:14:0)
[12:11:52.478] Build status: SCHEDULED
[12:11:52.478] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:15:0) after 2m28s
[12:14:20.554] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:15:0)
[12:14:20.576] Build status: SCHEDULED
[12:14:20.576] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:16:0) after 1m53s
[12:16:13.619] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:16:0)
[12:16:13.640] Build status: SCHEDULED
[12:16:13.640] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:17:0) after 6m2s
[12:22:16.077] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:17:0)
[12:22:16.104] Build status: SCHEDULED
[12:22:16.104] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:18:0) after 6m12s
[12:28:28.126] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:18:0)
[12:28:28.152] Build status: SCHEDULED
[12:28:28.152] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:19:0) after 6m59s
[12:35:27.510] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:19:0)
[12:35:27.536] Build status: SCHEDULED
[12:35:27.536] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:20:0) after 3m34s
[12:39:01.580] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:20:0)
[12:39:01.689] Build status: SCHEDULED
[12:39:01.689] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:21:0) after 7m8s
[12:46:09.793] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:21:0)
[12:46:09.981] Build status: SCHEDULED
[12:46:09.981] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:22:0) after 4m34s
[12:50:44.302] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:22:0)
[12:50:44.339] Build status: SCHEDULED
[12:50:44.339] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:23:0) after 8m25s
[12:59:09.441] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:23:0)
[12:59:09.573] Build status: SCHEDULED
[12:59:09.573] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:24:0) after 9m12s
[13:08:21.628] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:24:0)
[13:08:21.650] Build status: SCHEDULED
[13:08:21.650] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:25:0) after 7m56s
[13:16:17.946] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:25:0)
[13:16:17.984] Build status: SCHEDULED
[13:16:17.984] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:26:0) after 6m27s
[13:22:45.192] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:26:0)
[13:22:45.217] Build status: SCHEDULED
[13:22:45.217] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:27:0) after 4m45s
[13:27:30.423] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:27:0)
[13:27:30.450] Build status: SCHEDULED
[13:27:30.450] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:28:0) after 2m21s
[13:29:51.934] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:28:0)
[13:29:51.959] Build status: SCHEDULED
[13:29:51.959] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:29:0) after 4m11s
[13:34:02.990] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:29:0)
[13:34:03.014] Build status: SCHEDULED
[13:34:03.014] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:30:0) after 5m47s
[13:39:50.040] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:30:0)
[13:39:50.063] Build status: SCHEDULED
[13:39:50.063] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:31:0) after 9m38s
[13:49:28.081] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:31:0)
[13:49:28.160] Build status: SCHEDULED
[13:49:28.160] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:32:0) after 6m55s
[13:56:23.187] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:32:0)
[13:56:23.210] Build status: SCHEDULED
[13:56:23.210] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:33:0) after 6m58s
[14:03:21.343] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:33:0)
[14:03:21.370] Build status: SCHEDULED
[14:03:21.370] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:34:0) after 5m24s
[14:08:45.361] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:34:0)
[14:08:45.381] Build status: SCHEDULED
[14:08:45.381] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:35:0) after 8m9s
[14:16:54.781] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:35:0)
[14:16:54.817] Build status: SCHEDULED
[14:16:54.817] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:36:0) after 2m23s
[14:19:17.847] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:36:0)
[14:19:17.872] Build status: SCHEDULED
[14:19:17.872] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:37:0) after 8m58s
[14:28:15.989] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:37:0)
[14:28:16.011] Build status: SCHEDULED
[14:28:16.011] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:38:0) after 6m30s
[14:34:46.033] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:38:0)
[14:34:46.108] Build status: SCHEDULED
[14:34:46.108] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:39:0) after 3m16s
[14:38:02.256] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:39:0)
[14:38:02.292] Build status: SCHEDULED
[14:38:02.292] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:40:0) after 7m6s
[14:45:08.329] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:40:0)
[14:45:08.351] Build status: SCHEDULED
[14:45:08.351] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:41:0) after 6m11s
[14:51:19.702] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:41:0)
[14:51:19.728] Build status: SCHEDULED
[14:51:19.728] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:42:0) after 9m33s
[14:52:27.027] Received PubSub notification, asking Buildbucket for the build status
[14:52:27.063] Build status: STARTED
[15:00:52.892] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:42:0)
[15:00:52.929] Build status: STARTED
[15:00:52.929] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:44:0) after 1m49s
[15:02:42.005] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:44:0)
[15:02:42.027] Build status: STARTED
[15:02:42.027] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:45:0) after 1m12s
[15:03:54.606] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:45:0)
[15:03:54.635] Build status: STARTED
[15:03:54.635] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:46:0) after 5m46s
[15:09:40.705] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:46:0)
[15:09:40.734] Build status: STARTED
[15:09:40.734] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:47:0) after 9m45s
[15:19:25.763] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:47:0)
[15:19:25.786] Build status: STARTED
[15:19:25.786] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:48:0) after 5m58s
[15:25:23.955] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:48:0)
[15:25:23.978] Build status: STARTED
[15:25:23.978] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:49:0) after 1m59s
[15:27:23.011] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:49:0)
[15:27:23.037] Build status: STARTED
[15:27:23.037] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:50:0) after 2m11s
[15:29:34.157] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:50:0)
[15:29:34.183] Build status: STARTED
[15:29:34.183] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:51:0) after 6m29s
[15:36:03.224] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:51:0)
[15:36:03.287] Build status: STARTED
[15:36:03.288] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:52:0) after 6m14s
[15:42:17.344] Handling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:52:0)
[15:42:17.369] Build status: STARTED
[15:42:17.369] Scheduling timer "check-buildbucket-build-status" (r8/linux-internal:8961596246908784976:53:0) after 6m22s
[15:43:20.306] Received PubSub notification, asking Buildbucket for the build status
[15:43:20.331] Build:
{
"id": "8796166184283762337",
"builder": {
"project": "r8",
"bucket": "ci",
"builder": "linux-internal"
},
"number": 2889,
"createdBy": "project:r8",
"createTime": "2022-11-29T10:54:09.415142429Z",
"startTime": "2022-11-29T14:52:26.348367Z",
"endTime": "2022-11-29T15:43:19.722198634Z",
"updateTime": "2022-11-29T15:43:19.722198634Z",
"status": "FAILURE",
"input": {
"gitilesCommit": {
"host": "r8.googlesource.com",
"project": "r8",
"id": "29dc783003241692a40c7efd744139a4963fc82d",
"ref": "refs/heads/main"
}
},
"canary": true
}
[15:43:20.331] Invocation finished in 4h49m12.803052778s with status FAILED