[18:00:37.006] New invocation is queued and will start shortly
[18:00:37.006] Triggered by user:chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com
[18:00:38.087] Starting the invocation (attempt 1)
[18:00:38.119] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[18:00:38.119] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[18:00:38.119] Buildbucket request:
{
"bucket": "luci.infra.cron",
"client_operation_id": "9017558339647258160",
"parameters_json": "{\"builder_name\":\"Build From Tarball\",\"properties\":{\"$recipe_engine/scheduler\":{\"hostname\":\"luci-scheduler.appspot.com\",\"triggers\":[{\"buildbucket\":{\"properties\":{\"version\":\"91.0.4454.2\"},\"tags\":[\"parent_buildername:publish_tarball\",\"user_agent:recipe\"]},\"id\":\"848b944e-467a-4c60-bd9e-6c08e2c56d68\",\"title\":\"publish_tarball/0\"}]},\"version\":\"91.0.4454.2\"}}",
"pubsub_callback": {
"auth_token": "...",
"topic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
},
"tags": [
"builder:Build From Tarball",
"scheduler_invocation_id:9017558339647258160",
"scheduler_job_id:infra/Build From Tarball",
"user_agent:luci-scheduler",
"parent_buildername:publish_tarball",
"user_agent:recipe"
]
}
[18:00:38.506] Buildbucket response:
{
"build": {
"bucket": "luci.infra.cron",
"canary_preference": "PROD",
"created_by": "project:infra",
"created_ts": "1616349638240520",
"id": "8852128277690696608",
"parameters_json": "{\"builder_name\": \"Build From Tarball\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"buildbucket\": {\"properties\": {\"version\": \"91.0.4454.2\"}, \"tags\": [\"parent_buildername:publish_tarball\", \"user_agent:recipe\"]}, \"id\": \"848b944e-467a-4c60-bd9e-6c08e2c56d68\", \"title\": \"publish_tarball/0\"}]}, \"version\": \"91.0.4454.2\"}}",
"project": "infra",
"result_details_json": "{\"properties\": {}}",
"service_account": "chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"status": "SCHEDULED",
"status_changed_ts": "1616349638372352",
"tags": [
"builder:Build From Tarball",
"parent_buildername:publish_tarball",
"scheduler_invocation_id:9017558339647258160",
"scheduler_job_id:infra/Build From Tarball",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:log_location:logdog://logs.chromium.org/infra/buildbucket/cr-buildbucket.appspot.com/8852128277690696608/+/annotations",
"swarming_tag:luci_project:infra",
"swarming_tag:recipe_name:build_from_tarball",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/infra/infra",
"swarming_task_id:",
"user_agent:luci-scheduler",
"user_agent:recipe"
],
"updated_ts": "1616349638372520",
"url": "https://ci.chromium.org/b/8852128277690696608",
"utcnow_ts": "1616349638500577"
}
}
[18:00:38.506] Task URL: https://ci.chromium.org/b/8852128277690696608
[18:00:38.506] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:2:0) after 1m0s
[18:00:40.325] Received PubSub notification, asking Buildbucket for the build status
[18:00:40.399] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:01:38.529] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:2:0)
[18:01:38.559] Build status: STARTED
[18:01:38.559] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:4:0) after 8m36s
[18:10:14.575] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:4:0)
[18:10:14.599] Build status: STARTED
[18:10:14.599] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:5:0) after 2m41s
[18:12:55.711] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:5:0)
[18:12:55.711] Timer tick, asking Buildbucket for the build status
[18:12:55.902] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:12:55.902] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:6:0) after 1m0s
[18:13:56.735] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:6:0)
[18:13:56.764] Build status: STARTED
[18:13:56.764] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:7:0) after 3m3s
[18:16:59.781] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:7:0)
[18:16:59.809] Build status: STARTED
[18:16:59.809] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:8:0) after 4m19s
[18:21:18.814] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:8:0)
[18:21:18.814] Timer tick, asking Buildbucket for the build status
[18:21:19.088] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:21:19.088] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:9:0) after 1m0s
[18:22:19.198] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:9:0)
[18:22:19.230] Build status: STARTED
[18:22:19.230] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:10:0) after 3m5s
[18:25:24.258] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:10:0)
[18:25:24.282] Build status: STARTED
[18:25:24.282] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:11:0) after 1m24s
[18:26:48.518] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:11:0)
[18:26:48.543] Build status: STARTED
[18:26:48.543] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:12:0) after 1m57s
[18:28:45.769] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:12:0)
[18:28:45.794] Build status: STARTED
[18:28:45.794] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:13:0) after 6m30s
[18:35:15.811] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:13:0)
[18:35:15.837] Build status: STARTED
[18:35:15.837] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:14:0) after 5m38s
[18:40:53.855] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:14:0)
[18:40:53.880] Build status: STARTED
[18:40:53.880] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:15:0) after 5m18s
[18:46:11.997] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:15:0)
[18:46:12.026] Build status: STARTED
[18:46:12.026] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:16:0) after 3m24s
[18:49:36.040] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:16:0)
[18:49:36.040] Timer tick, asking Buildbucket for the build status
[18:49:36.142] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:49:36.142] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:17:0) after 1m0s
[18:50:36.244] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:17:0)
[18:50:36.320] Build status: STARTED
[18:50:36.320] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:18:0) after 1m17s
[18:51:53.306] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:18:0)
[18:51:53.328] Build status: STARTED
[18:51:53.328] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:19:0) after 5m54s
[18:57:48.837] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:19:0)
[18:57:48.861] Build status: STARTED
[18:57:48.861] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:20:0) after 4m19s
[19:02:07.879] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:20:0)
[19:02:07.905] Build status: STARTED
[19:02:07.905] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:21:0) after 9m1s
[19:11:22.267] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:21:0)
[19:11:22.267] Timer tick, asking Buildbucket for the build status
[19:11:22.349] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:11:22.349] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:22:0) after 1m0s
[19:12:22.366] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:22:0)
[19:12:22.392] Build status: STARTED
[19:12:22.392] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:23:0) after 8m7s
[19:20:29.417] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:23:0)
[19:20:29.417] Timer tick, asking Buildbucket for the build status
[19:20:29.488] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:20:29.488] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:24:0) after 1m0s
[19:21:29.507] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:24:0)
[19:21:29.536] Build status: STARTED
[19:21:29.536] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:25:0) after 5m35s
[19:27:04.552] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:25:0)
[19:27:04.620] Build status: STARTED
[19:27:04.620] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:26:0) after 7m10s
[19:34:14.643] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:26:0)
[19:34:14.671] Build status: STARTED
[19:34:14.671] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:27:0) after 6m38s
[19:40:52.699] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:27:0)
[19:40:52.728] Build status: STARTED
[19:40:52.728] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:28:0) after 7m7s
[19:47:59.744] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:28:0)
[19:47:59.744] Timer tick, asking Buildbucket for the build status
[19:47:59.857] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:47:59.857] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:29:0) after 1m0s
[19:48:59.874] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:29:0)
[19:48:59.916] Build status: STARTED
[19:48:59.916] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:30:0) after 5m0s
[19:54:00.151] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:30:0)
[19:54:00.151] Timer tick, asking Buildbucket for the build status
[19:54:00.249] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:54:00.249] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:31:0) after 1m0s
[19:55:00.380] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:31:0)
[19:55:00.380] Timer tick, asking Buildbucket for the build status
[19:55:00.460] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:55:00.460] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:32:0) after 1m0s
[19:56:00.587] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:32:0)
[19:56:00.587] Timer tick, asking Buildbucket for the build status
[19:56:00.809] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:56:00.809] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:33:0) after 1m0s
[19:57:00.893] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:33:0)
[19:57:00.893] Timer tick, asking Buildbucket for the build status
[19:57:00.967] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:57:00.967] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:34:0) after 1m0s
[19:58:01.342] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:34:0)
[19:58:01.342] Timer tick, asking Buildbucket for the build status
[19:58:01.407] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:58:01.407] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:35:0) after 1m0s
[19:59:01.604] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:35:0)
[19:59:01.604] Timer tick, asking Buildbucket for the build status
[19:59:01.811] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:59:01.812] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:36:0) after 1m0s
[20:00:01.840] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:36:0)
[20:00:01.882] Build status: STARTED
[20:00:01.882] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:37:0) after 9m23s
[20:09:24.918] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:37:0)
[20:09:24.942] Build status: STARTED
[20:09:24.942] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:38:0) after 9m26s
[20:18:50.966] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:38:0)
[20:18:50.966] Timer tick, asking Buildbucket for the build status
[20:18:51.043] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:18:51.043] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:39:0) after 1m0s
[20:19:51.181] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:39:0)
[20:19:51.181] Timer tick, asking Buildbucket for the build status
[20:19:51.311] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:19:51.311] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:40:0) after 1m0s
[20:20:51.619] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:40:0)
[20:20:51.619] Timer tick, asking Buildbucket for the build status
[20:20:51.841] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:20:51.841] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:41:0) after 1m0s
[20:21:51.858] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:41:0)
[20:21:51.888] Build status: STARTED
[20:21:51.888] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:42:0) after 8m15s
[20:30:06.910] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:42:0)
[20:30:06.911] Timer tick, asking Buildbucket for the build status
[20:30:07.224] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:30:07.225] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:43:0) after 1m0s
[20:31:07.249] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:43:0)
[20:31:07.294] Build status: STARTED
[20:31:07.294] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:44:0) after 4m52s
[20:35:59.313] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:44:0)
[20:35:59.347] Build status: STARTED
[20:35:59.347] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:45:0) after 8m54s
[20:44:53.389] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:45:0)
[20:44:53.389] Timer tick, asking Buildbucket for the build status
[20:44:53.552] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:44:53.552] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:46:0) after 1m0s
[20:45:53.568] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:46:0)
[20:45:53.590] Build status: STARTED
[20:45:53.590] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:47:0) after 1m58s
[20:47:51.690] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:47:0)
[20:47:51.690] Timer tick, asking Buildbucket for the build status
[20:47:51.772] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:47:51.772] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:48:0) after 1m0s
[20:48:51.848] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:48:0)
[20:48:51.849] Timer tick, asking Buildbucket for the build status
[20:48:51.913] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:48:51.913] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:49:0) after 1m0s
[20:49:51.934] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:49:0)
[20:49:51.960] Build status: STARTED
[20:49:51.960] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:50:0) after 8m2s
[20:57:53.986] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:50:0)
[20:57:53.986] Timer tick, asking Buildbucket for the build status
[20:57:54.055] Build 8852128277690696608: status "STARTED", result "", failure_reason "", cancelation_reason ""
[20:57:54.055] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:51:0) after 1m0s
[20:58:54.075] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:51:0)
[20:58:54.108] Build status: STARTED
[20:58:54.108] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:52:0) after 2m52s
[21:01:46.228] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:52:0)
[21:01:46.268] Build status: STARTED
[21:01:46.268] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9017558339647258160:53:0) after 6m19s
[21:07:21.427] Received PubSub notification, asking Buildbucket for the build status
[21:07:21.455] Build:
{
"id": "8852128277690696608",
"builder": {
"project": "infra",
"bucket": "cron",
"builder": "Build From Tarball"
},
"createdBy": "project:infra",
"createTime": "2021-03-21T18:00:38.240520Z",
"startTime": "2021-03-21T18:00:39.790284Z",
"endTime": "2021-03-21T21:07:21.038553873Z",
"updateTime": "2021-03-21T21:07:21.038853499Z",
"status": "SUCCESS",
"input": {
}
}
[21:07:21.455] Invocation finished in 3h6m44.463848315s with status SUCCEEDED