[23:15:08.731] New invocation is queued and will start shortly
[23:15:08.731] Triggered by user:chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com
[23:15:10.301] Starting the invocation (attempt 1)
[23:15:10.400] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[23:15:10.400] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[23:15:10.400] Buildbucket request:
{
"bucket": "luci.infra.cron",
"client_operation_id": "9099619402768428336",
"parameters_json": "{\"builder_name\":\"Build From Tarball\",\"properties\":{\"version\":\"71.0.3563.0\"}}",
"pubsub_callback": {
"auth_token": "...",
"topic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
},
"tags": [
"builder:Build From Tarball",
"scheduler_invocation_id:9099619402768428336",
"scheduler_job_id:infra/Build From Tarball",
"user_agent:luci-scheduler",
"parent_buildername:publish_tarball",
"user_agent:recipe"
]
}
[23:15:11.829] Buildbucket response:
{
"build": {
"bucket": "luci.infra.cron",
"canary_preference": "AUTO",
"created_by": "user:luci-scheduler@appspot.gserviceaccount.com",
"created_ts": "1538090110519555",
"id": "8934189340230829936",
"lease_expiration_ts": "1538208911629821",
"lease_key": "1275428410",
"parameters_json": "{\"builder_name\": \"Build From Tarball\", \"properties\": {\"version\": \"71.0.3563.0\"}}",
"project": "infra",
"result_details_json": "null",
"service_account": "chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"status": "SCHEDULED",
"status_changed_ts": "1538090111634469",
"tags": [
"builder:Build From Tarball",
"parent_buildername:publish_tarball",
"scheduler_invocation_id:9099619402768428336",
"scheduler_job_id:infra/Build From Tarball",
"swarming_dimension:builder:Build From Tarball",
"swarming_dimension:caches:builder_99d5fe30e8b6c78ca136ab5e547c67467b176b4f7d67cf49cf682cf48a330f19_v2",
"swarming_dimension:cpu:x86-64",
"swarming_dimension:os:Ubuntu-14.04",
"swarming_dimension:pool:luci.infra.cron",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:buildbucket_bucket:luci.infra.cron",
"swarming_tag:buildbucket_build_id:8934189340230829936",
"swarming_tag:buildbucket_hostname:cr-buildbucket.appspot.com",
"swarming_tag:buildbucket_template_canary:0",
"swarming_tag:buildbucket_template_revision:4c790cbde9342069ed9b59b6709c8807b14f2913",
"swarming_tag:builder:Build From Tarball",
"swarming_tag:caches:builder_99d5fe30e8b6c78ca136ab5e547c67467b176b4f7d67cf49cf682cf48a330f19_v2",
"swarming_tag:cpu:x86-64",
"swarming_tag:log_location:logdog://logs.chromium.org/infra/buildbucket/cr-buildbucket.appspot.com/8934189340230829936/+/annotations",
"swarming_tag:luci_project:infra",
"swarming_tag:os:Ubuntu-14.04",
"swarming_tag:parent_buildername:publish_tarball",
"swarming_tag:pool:luci.infra.cron",
"swarming_tag:priority:30",
"swarming_tag:recipe_name:build_from_tarball",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/infra/infra",
"swarming_tag:scheduler_invocation_id:9099619402768428336",
"swarming_tag:scheduler_job_id:infra/Build From Tarball",
"swarming_tag:service_account:chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"swarming_tag:swarming.pool.template:skip",
"swarming_tag:swarming.pool.version:6e26dc5d93a41d5e3202708c9bc0ec938c784188",
"swarming_tag:user:None",
"swarming_tag:user_agent:luci-scheduler",
"swarming_tag:user_agent:recipe",
"swarming_tag:vpython:native-python-wrapper",
"swarming_task_id:40362217d802ca10",
"user_agent:luci-scheduler",
"user_agent:recipe"
],
"updated_ts": "1538090111634598",
"url": "https://ci.chromium.org/p/infra/builds/b8934189340230829936",
"utcnow_ts": "1538090111801244"
}
}
[23:15:11.829] Task URL: https://ci.chromium.org/p/infra/builds/b8934189340230829936
[23:15:11.829] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:2:0) after 1m0s
[23:15:16.733] Received PubSub notification, asking Buildbucket for the build status
[23:15:16.858] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:16:11.870] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:2:0)
[23:16:11.870] Timer tick, asking Buildbucket for the build status
[23:16:11.917] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:16:11.917] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:4:0) after 1m0s
[23:17:11.940] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:4:0)
[23:17:11.940] Timer tick, asking Buildbucket for the build status
[23:17:12.012] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:17:12.012] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:5:0) after 1m0s
[23:18:12.043] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:5:0)
[23:18:12.043] Timer tick, asking Buildbucket for the build status
[23:18:12.090] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:18:12.091] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:6:0) after 1m0s
[23:19:12.190] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:6:0)
[23:19:12.190] Timer tick, asking Buildbucket for the build status
[23:19:12.245] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:19:12.245] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:7:0) after 1m0s
[23:20:12.267] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:7:0)
[23:20:12.267] Timer tick, asking Buildbucket for the build status
[23:20:12.384] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:20:12.384] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:8:0) after 1m0s
[23:21:12.415] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:8:0)
[23:21:12.415] Timer tick, asking Buildbucket for the build status
[23:21:12.476] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:21:12.476] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:9:0) after 1m0s
[23:22:12.493] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:9:0)
[23:22:12.493] Timer tick, asking Buildbucket for the build status
[23:22:12.565] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:22:12.565] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:10:0) after 1m0s
[23:23:12.584] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:10:0)
[23:23:12.584] Timer tick, asking Buildbucket for the build status
[23:23:12.952] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:23:12.952] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:11:0) after 1m0s
[23:24:12.983] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:11:0)
[23:24:12.983] Timer tick, asking Buildbucket for the build status
[23:24:13.086] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:24:13.086] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:12:0) after 1m0s
[23:25:13.148] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:12:0)
[23:25:13.148] Timer tick, asking Buildbucket for the build status
[23:25:13.247] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:25:13.247] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:13:0) after 1m0s
[23:26:13.268] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:13:0)
[23:26:13.268] Timer tick, asking Buildbucket for the build status
[23:26:13.328] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:26:13.328] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:14:0) after 1m0s
[23:27:13.347] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:14:0)
[23:27:13.347] Timer tick, asking Buildbucket for the build status
[23:27:13.470] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:27:13.470] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:15:0) after 1m0s
[23:28:13.518] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:15:0)
[23:28:13.518] Timer tick, asking Buildbucket for the build status
[23:28:13.582] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:28:13.582] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:16:0) after 1m0s
[23:29:13.602] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:16:0)
[23:29:13.602] Timer tick, asking Buildbucket for the build status
[23:29:13.660] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:29:13.660] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:17:0) after 1m0s
[23:30:13.702] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:17:0)
[23:30:13.702] Timer tick, asking Buildbucket for the build status
[23:30:13.767] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:30:13.767] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:18:0) after 1m0s
[23:31:13.796] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:18:0)
[23:31:13.796] Timer tick, asking Buildbucket for the build status
[23:31:13.863] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:31:13.863] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:19:0) after 1m0s
[23:32:13.882] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:19:0)
[23:32:13.882] Timer tick, asking Buildbucket for the build status
[23:32:14.006] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:32:14.006] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:20:0) after 1m0s
[23:33:14.031] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:20:0)
[23:33:14.031] Timer tick, asking Buildbucket for the build status
[23:33:14.091] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:33:14.091] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:21:0) after 1m0s
[23:34:14.174] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:21:0)
[23:34:14.174] Timer tick, asking Buildbucket for the build status
[23:34:14.236] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:34:14.236] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:22:0) after 1m0s
[23:35:14.256] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:22:0)
[23:35:14.256] Timer tick, asking Buildbucket for the build status
[23:35:14.315] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:35:14.315] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:23:0) after 1m0s
[23:36:14.346] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:23:0)
[23:36:14.346] Timer tick, asking Buildbucket for the build status
[23:36:14.405] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:36:14.405] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:24:0) after 1m0s
[23:37:14.426] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:24:0)
[23:37:14.426] Timer tick, asking Buildbucket for the build status
[23:37:14.601] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:37:14.602] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:25:0) after 1m0s
[23:38:14.615] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:25:0)
[23:38:14.615] Timer tick, asking Buildbucket for the build status
[23:38:14.686] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:38:14.686] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:26:0) after 1m0s
[23:39:14.705] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:26:0)
[23:39:14.705] Timer tick, asking Buildbucket for the build status
[23:39:14.866] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:39:14.866] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:27:0) after 1m0s
[23:40:14.889] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:27:0)
[23:40:14.889] Timer tick, asking Buildbucket for the build status
[23:40:14.965] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:40:14.965] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:28:0) after 1m0s
[23:41:14.998] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:28:0)
[23:41:14.998] Timer tick, asking Buildbucket for the build status
[23:41:15.049] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:41:15.049] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:29:0) after 1m0s
[23:42:15.073] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:29:0)
[23:42:15.073] Timer tick, asking Buildbucket for the build status
[23:42:15.107] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:42:15.107] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:30:0) after 1m0s
[23:43:15.126] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:30:0)
[23:43:15.126] Timer tick, asking Buildbucket for the build status
[23:43:15.229] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:43:15.229] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:31:0) after 1m0s
[23:44:15.254] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:31:0)
[23:44:15.254] Timer tick, asking Buildbucket for the build status
[23:44:15.321] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:44:15.321] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:32:0) after 1m0s
[23:45:15.355] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:32:0)
[23:45:15.355] Timer tick, asking Buildbucket for the build status
[23:45:15.428] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:45:15.428] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:33:0) after 1m0s
[23:46:15.447] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:33:0)
[23:46:15.447] Timer tick, asking Buildbucket for the build status
[23:46:15.575] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:46:15.575] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:34:0) after 1m0s
[23:47:15.597] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:34:0)
[23:47:15.597] Timer tick, asking Buildbucket for the build status
[23:47:15.668] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:47:15.668] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:35:0) after 1m0s
[23:48:15.777] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:35:0)
[23:48:15.777] Timer tick, asking Buildbucket for the build status
[23:48:15.818] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:48:15.818] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:36:0) after 1m0s
[23:49:15.834] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:36:0)
[23:49:15.834] Timer tick, asking Buildbucket for the build status
[23:49:15.917] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:49:15.917] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:37:0) after 1m0s
[23:50:15.942] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:37:0)
[23:50:15.942] Timer tick, asking Buildbucket for the build status
[23:50:15.988] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:50:15.988] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:38:0) after 1m0s
[23:51:16.012] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:38:0)
[23:51:16.012] Timer tick, asking Buildbucket for the build status
[23:51:16.076] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:51:16.076] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:39:0) after 1m0s
[23:52:16.102] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:39:0)
[23:52:16.102] Timer tick, asking Buildbucket for the build status
[23:52:16.184] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:52:16.185] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:40:0) after 1m0s
[23:53:16.249] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:40:0)
[23:53:16.249] Timer tick, asking Buildbucket for the build status
[23:53:16.366] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:53:16.366] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:41:0) after 1m0s
[23:54:16.432] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:41:0)
[23:54:16.432] Timer tick, asking Buildbucket for the build status
[23:54:16.506] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:54:16.506] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:42:0) after 1m0s
[23:55:16.529] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:42:0)
[23:55:16.529] Timer tick, asking Buildbucket for the build status
[23:55:16.609] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:55:16.609] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:43:0) after 1m0s
[23:56:16.694] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:43:0)
[23:56:16.694] Timer tick, asking Buildbucket for the build status
[23:56:16.779] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:56:16.779] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:44:0) after 1m0s
[23:57:16.813] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:44:0)
[23:57:16.813] Timer tick, asking Buildbucket for the build status
[23:57:16.918] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:57:16.918] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:45:0) after 1m0s
[23:58:16.935] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:45:0)
[23:58:16.935] Timer tick, asking Buildbucket for the build status
[23:58:17.090] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:58:17.090] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:46:0) after 1m0s
[23:59:17.111] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:46:0)
[23:59:17.111] Timer tick, asking Buildbucket for the build status
[23:59:17.300] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[23:59:17.300] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:47:0) after 1m0s
[00:00:17.317] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:47:0)
[00:00:17.317] Timer tick, asking Buildbucket for the build status
[00:00:17.393] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:00:17.393] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:48:0) after 1m0s
[00:01:17.411] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:48:0)
[00:01:17.411] Timer tick, asking Buildbucket for the build status
[00:01:17.590] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:01:17.591] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:49:0) after 1m0s
[00:02:17.610] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:49:0)
[00:02:17.610] Timer tick, asking Buildbucket for the build status
[00:02:17.670] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:02:17.670] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:50:0) after 1m0s
[00:03:17.706] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:50:0)
[00:03:17.706] Timer tick, asking Buildbucket for the build status
[00:03:17.744] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:03:17.744] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:51:0) after 1m0s
[00:04:17.769] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:51:0)
[00:04:17.769] Timer tick, asking Buildbucket for the build status
[00:04:17.829] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:04:17.829] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:52:0) after 1m0s
[00:05:17.855] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:52:0)
[00:05:17.855] Timer tick, asking Buildbucket for the build status
[00:05:17.938] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:05:17.938] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:53:0) after 1m0s
[00:06:17.960] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:53:0)
[00:06:17.960] Timer tick, asking Buildbucket for the build status
[00:06:18.060] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:06:18.060] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:54:0) after 1m0s
[00:07:18.084] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:54:0)
[00:07:18.084] Timer tick, asking Buildbucket for the build status
[00:07:18.160] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:07:18.160] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:55:0) after 1m0s
[00:08:18.194] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:55:0)
[00:08:18.194] Timer tick, asking Buildbucket for the build status
[00:08:18.236] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:08:18.236] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:56:0) after 1m0s
[00:09:18.258] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:56:0)
[00:09:18.258] Timer tick, asking Buildbucket for the build status
[00:09:18.309] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:09:18.309] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:57:0) after 1m0s
[00:10:18.341] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:57:0)
[00:10:18.341] Timer tick, asking Buildbucket for the build status
[00:10:18.528] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:10:18.528] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:58:0) after 1m0s
[00:11:18.555] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:58:0)
[00:11:18.555] Timer tick, asking Buildbucket for the build status
[00:11:18.613] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:11:18.613] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:59:0) after 1m0s
[00:12:18.645] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:59:0)
[00:12:18.645] Timer tick, asking Buildbucket for the build status
[00:12:18.791] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:12:18.791] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:60:0) after 1m0s
[00:13:18.814] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:60:0)
[00:13:18.815] Timer tick, asking Buildbucket for the build status
[00:13:18.925] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:13:18.925] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:61:0) after 1m0s
[00:14:18.945] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:61:0)
[00:14:18.945] Timer tick, asking Buildbucket for the build status
[00:14:18.989] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:14:18.989] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:62:0) after 1m0s
[00:15:19.012] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:62:0)
[00:15:19.012] Timer tick, asking Buildbucket for the build status
[00:15:19.085] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:15:19.085] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:63:0) after 1m0s
[00:16:19.113] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:63:0)
[00:16:19.113] Timer tick, asking Buildbucket for the build status
[00:16:19.232] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:16:19.232] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:64:0) after 1m0s
[00:17:19.281] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:64:0)
[00:17:19.281] Timer tick, asking Buildbucket for the build status
[00:17:19.361] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:17:19.361] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:65:0) after 1m0s
[00:18:19.476] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:65:0)
[00:18:19.476] Timer tick, asking Buildbucket for the build status
[00:18:19.525] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:18:19.525] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:66:0) after 1m0s
[00:19:19.555] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:66:0)
[00:19:19.555] Timer tick, asking Buildbucket for the build status
[00:19:19.632] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:19:19.632] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:67:0) after 1m0s
[00:20:19.683] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:67:0)
[00:20:19.683] Timer tick, asking Buildbucket for the build status
[00:20:19.740] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:20:19.740] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:68:0) after 1m0s
[00:21:19.787] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:68:0)
[00:21:19.787] Timer tick, asking Buildbucket for the build status
[00:21:19.890] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:21:19.890] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:69:0) after 1m0s
[00:22:19.911] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:69:0)
[00:22:19.911] Timer tick, asking Buildbucket for the build status
[00:22:19.981] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:22:19.981] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:70:0) after 1m0s
[00:23:20.006] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:70:0)
[00:23:20.006] Timer tick, asking Buildbucket for the build status
[00:23:20.153] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:23:20.153] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:71:0) after 1m0s
[00:24:20.174] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:71:0)
[00:24:20.174] Timer tick, asking Buildbucket for the build status
[00:24:20.215] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:24:20.215] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:72:0) after 1m0s
[00:25:20.242] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:72:0)
[00:25:20.242] Timer tick, asking Buildbucket for the build status
[00:25:20.318] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:25:20.318] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:73:0) after 1m0s
[00:26:20.376] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:73:0)
[00:26:20.376] Timer tick, asking Buildbucket for the build status
[00:26:20.788] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:26:20.788] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:74:0) after 1m0s
[00:27:20.807] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:74:0)
[00:27:20.807] Timer tick, asking Buildbucket for the build status
[00:27:20.933] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:27:20.933] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:75:0) after 1m0s
[00:28:20.962] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:75:0)
[00:28:20.962] Timer tick, asking Buildbucket for the build status
[00:28:20.997] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:28:20.997] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:76:0) after 1m0s
[00:29:21.019] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:76:0)
[00:29:21.019] Timer tick, asking Buildbucket for the build status
[00:29:21.091] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:29:21.091] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:77:0) after 1m0s
[00:30:21.139] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:77:0)
[00:30:21.139] Timer tick, asking Buildbucket for the build status
[00:30:21.282] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:30:21.282] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:78:0) after 1m0s
[00:31:21.315] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:78:0)
[00:31:21.315] Timer tick, asking Buildbucket for the build status
[00:31:21.388] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:31:21.388] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:79:0) after 1m0s
[00:32:21.419] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:79:0)
[00:32:21.419] Timer tick, asking Buildbucket for the build status
[00:32:21.454] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:32:21.454] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:80:0) after 1m0s
[00:33:21.476] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:80:0)
[00:33:21.476] Timer tick, asking Buildbucket for the build status
[00:33:21.530] Build 8934189340230829936: status "STARTED", result "", failure_reason "", cancelation_reason ""
[00:33:21.530] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9099619402768428336:81:0) after 1m0s
[00:34:09.888] Received PubSub notification, asking Buildbucket for the build status
[00:34:09.933] Build 8934189340230829936: status "COMPLETED", result "FAILURE", failure_reason "BUILD_FAILURE", cancelation_reason ""
[00:34:09.933] Buildbucket build:
{
"build": {
"bucket": "luci.infra.cron",
"canary_preference": "AUTO",
"completed_ts": "1538094847411366",
"created_by": "user:luci-scheduler@appspot.gserviceaccount.com",
"created_ts": "1538090110519555",
"failure_reason": "BUILD_FAILURE",
"id": "8934189340230829936",
"parameters_json": "{\"builder_name\": \"Build From Tarball\", \"properties\": {\"version\": \"71.0.3563.0\"}}",
"project": "infra",
"result": "FAILURE",
"result_details_json": "{\"ui\": {\"info\": \"Failure Build chrome.\"}, \"build_run_result\": {\"infraFailure\": null, \"recipeResult\": {\"failure\": {\"failure\": {\"step\": \"Build chrome.\"}, \"humanReason\": \"Step('Build chrome.') failed with return_code 1\"}}, \"recipeExitCode\": {\"value\": 1}, \"recipe\": {\"name\": \"build_from_tarball\", \"repository\": \"\", \"revision\": \"\"}, \"annotationUrl\": \"logdog://logs.chromium.org/infra/buildbucket/cr-buildbucket.appspot.com/8934189340230829936/+/annotations\"}, \"swarming\": {\"bot_dimensions\": {\"machine_type\": [\"n1-standard-8\"], \"inside_docker\": [\"0\"], \"python\": [\"2.7.6\"], \"builder\": [\"Build From Tarball\"], \"kvm\": [\"1\"], \"cpu\": [\"x86\", \"x86-64\", \"x86-64-Broadwell_GCE\", \"x86-64-avx2\"], \"server_version\": [\"3793-c7dcd56\"], \"image\": [\"chrome-trusty-18091700-38cc06ee3ee\"], \"gpu\": [\"none\"], \"cores\": [\"8\"], \"zone\": [\"us\", \"us-west\", \"us-west1\", \"us-west1-c\"], \"os\": [\"Linux\", \"Ubuntu\", \"Ubuntu-14.04\"], \"id\": [\"gce-trusty-e833d7b0-us-west1-c-0l7j\"], \"pool\": [\"luci.infra.cron\"], \"caches\": [\"vpython\"]}}, \"properties\": {\"$recipe_engine/path\": {\"cache_dir\": \"/b/s/w/ir/cache\", \"temp_dir\": \"/b/s/w/ir/tmp/rt\"}, \"buildername\": \"Build From Tarball\", \"recipe\": \"build_from_tarball\", \"$recipe_engine/runtime\": {\"is_experimental\": false, \"is_luci\": true}, \"buildbucket\": {\"hostname\": \"cr-buildbucket.appspot.com\", \"build\": {\"created_ts\": 1538090110519555, \"tags\": [\"builder:Build From Tarball\", \"parent_buildername:publish_tarball\", \"scheduler_invocation_id:9099619402768428336\", \"scheduler_job_id:infra/Build From Tarball\", \"user_agent:luci-scheduler\", \"user_agent:recipe\"], \"bucket\": \"luci.infra.cron\", \"created_by\": \"user:luci-scheduler@appspot.gserviceaccount.com\", \"project\": \"infra\", \"id\": \"8934189340230829936\"}}, \"version\": \"71.0.3563.0\", \"path_config\": \"generic\", \"bot_id\": \"gce-trusty-e833d7b0-us-west1-c-0l7j\"}}",
"service_account": "chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"started_ts": "1538090116023256",
"status": "COMPLETED",
"status_changed_ts": "1538094849360161",
"tags": [
"builder:Build From Tarball",
"parent_buildername:publish_tarball",
"scheduler_invocation_id:9099619402768428336",
"scheduler_job_id:infra/Build From Tarball",
"swarming_dimension:builder:Build From Tarball",
"swarming_dimension:caches:builder_99d5fe30e8b6c78ca136ab5e547c67467b176b4f7d67cf49cf682cf48a330f19_v2",
"swarming_dimension:cpu:x86-64",
"swarming_dimension:os:Ubuntu-14.04",
"swarming_dimension:pool:luci.infra.cron",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:buildbucket_bucket:luci.infra.cron",
"swarming_tag:buildbucket_build_id:8934189340230829936",
"swarming_tag:buildbucket_hostname:cr-buildbucket.appspot.com",
"swarming_tag:buildbucket_template_canary:0",
"swarming_tag:buildbucket_template_revision:4c790cbde9342069ed9b59b6709c8807b14f2913",
"swarming_tag:builder:Build From Tarball",
"swarming_tag:caches:builder_99d5fe30e8b6c78ca136ab5e547c67467b176b4f7d67cf49cf682cf48a330f19_v2",
"swarming_tag:cpu:x86-64",
"swarming_tag:log_location:logdog://logs.chromium.org/infra/buildbucket/cr-buildbucket.appspot.com/8934189340230829936/+/annotations",
"swarming_tag:luci_project:infra",
"swarming_tag:os:Ubuntu-14.04",
"swarming_tag:parent_buildername:publish_tarball",
"swarming_tag:pool:luci.infra.cron",
"swarming_tag:priority:30",
"swarming_tag:recipe_name:build_from_tarball",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/infra/infra",
"swarming_tag:scheduler_invocation_id:9099619402768428336",
"swarming_tag:scheduler_job_id:infra/Build From Tarball",
"swarming_tag:service_account:chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"swarming_tag:swarming.pool.template:skip",
"swarming_tag:swarming.pool.version:6e26dc5d93a41d5e3202708c9bc0ec938c784188",
"swarming_tag:user:None",
"swarming_tag:user_agent:luci-scheduler",
"swarming_tag:user_agent:recipe",
"swarming_tag:vpython:native-python-wrapper",
"swarming_task_id:40362217d802ca10",
"user_agent:luci-scheduler",
"user_agent:recipe"
],
"updated_ts": "1538094849364923",
"url": "https://ci.chromium.org/p/infra/builds/b8934189340230829936",
"utcnow_ts": "1538094849921718"
}
}
[00:34:09.933] Invocation finished in 1h19m1.217699716s with status FAILED