[05:38:30.393] New invocation is queued and will start shortly
[05:38:30.393] Triggered by user:chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com
[05:38:31.601] Starting the invocation (attempt 1)
[05:38:31.679] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[05:38:31.679] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[05:38:31.679] Buildbucket request:
{
"bucket": "luci.infra.cron",
"client_operation_id": "9055836949015347456",
"parameters_json": "{\"builder_name\":\"Build From Tarball\",\"properties\":{\"$recipe_engine/scheduler\":{\"hostname\":\"luci-scheduler.appspot.com\",\"triggers\":[{\"buildbucket\":{\"properties\":{\"version\":\"81.0.4035.5\"},\"tags\":[\"parent_buildername:publish_tarball\",\"user_agent:recipe\"]},\"id\":\"5c53e18d-8701-4c4b-b72c-4b58bc52cc23\",\"title\":\"publish_tarball/0\"}]},\"version\":\"81.0.4035.5\"}}",
"pubsub_callback": {
"auth_token": "...",
"topic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
},
"tags": [
"builder:Build From Tarball",
"scheduler_invocation_id:9055836949015347456",
"scheduler_job_id:infra/Build From Tarball",
"user_agent:luci-scheduler",
"parent_buildername:publish_tarball",
"user_agent:recipe"
]
}
[05:38:32.096] Buildbucket response:
{
"build": {
"bucket": "luci.infra.cron",
"canary_preference": "PROD",
"created_by": "project:infra",
"created_ts": "1579844311797578",
"id": "8890406886871293760",
"parameters_json": "{\"builder_name\": \"Build From Tarball\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"buildbucket\": {\"properties\": {\"version\": \"81.0.4035.5\"}, \"tags\": [\"parent_buildername:publish_tarball\", \"user_agent:recipe\"]}, \"id\": \"5c53e18d-8701-4c4b-b72c-4b58bc52cc23\", \"title\": \"publish_tarball/0\"}]}, \"version\": \"81.0.4035.5\"}}",
"project": "infra",
"result_details_json": "{\"properties\": {}}",
"service_account": "chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"status": "SCHEDULED",
"status_changed_ts": "1579844311949822",
"tags": [
"builder:Build From Tarball",
"parent_buildername:publish_tarball",
"scheduler_invocation_id:9055836949015347456",
"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/8890406886871293760/+/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": "1579844311949938",
"url": "https://ci.chromium.org/b/8890406886871293760",
"utcnow_ts": "1579844312081753"
}
}
[05:38:32.096] Task URL: https://ci.chromium.org/b/8890406886871293760
[05:38:32.096] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:2:0) after 1m0s
[05:39:32.200] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:2:0)
[05:39:32.200] Timer tick, asking Buildbucket for the build status
[05:39:32.366] Build 8890406886871293760: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[05:39:32.366] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:3:0) after 1m0s
[05:40:32.446] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:3:0)
[05:40:32.446] Timer tick, asking Buildbucket for the build status
[05:40:32.604] Build 8890406886871293760: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[05:40:32.604] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:4:0) after 1m0s
[05:41:32.696] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:4:0)
[05:41:32.696] Timer tick, asking Buildbucket for the build status
[05:41:32.795] Build 8890406886871293760: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[05:41:32.795] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:5:0) after 1m0s
[05:42:32.828] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:5:0)
[05:42:32.829] Timer tick, asking Buildbucket for the build status
[05:42:33.254] Build 8890406886871293760: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[05:42:33.254] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:6:0) after 1m0s
[05:43:33.249] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:6:0)
[05:43:33.249] Timer tick, asking Buildbucket for the build status
[05:43:33.371] Build 8890406886871293760: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[05:43:33.371] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:7:0) after 1m0s
[05:43:48.066] Received PubSub notification, asking Buildbucket for the build status
[05:43:48.280] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:44:33.407] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:7:0)
[05:44:33.407] Timer tick, asking Buildbucket for the build status
[05:44:33.644] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:44:33.644] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:9:0) after 1m0s
[05:45:33.654] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:9:0)
[05:45:33.654] Timer tick, asking Buildbucket for the build status
[05:45:33.926] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:45:33.926] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:10:0) after 1m0s
[05:46:33.967] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:10:0)
[05:46:33.968] Timer tick, asking Buildbucket for the build status
[05:46:34.099] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:46:34.099] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:11:0) after 1m0s
[05:47:34.142] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:11:0)
[05:47:34.142] Timer tick, asking Buildbucket for the build status
[05:47:34.263] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:47:34.263] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:12:0) after 1m0s
[05:48:34.393] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:12:0)
[05:48:34.393] Timer tick, asking Buildbucket for the build status
[05:48:34.883] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:48:34.883] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:13:0) after 1m0s
[05:49:34.901] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:13:0)
[05:49:34.901] Timer tick, asking Buildbucket for the build status
[05:49:34.966] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:49:34.966] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:14:0) after 1m0s
[05:50:34.985] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:14:0)
[05:50:34.985] Timer tick, asking Buildbucket for the build status
[05:50:35.092] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:50:35.092] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:15:0) after 1m0s
[05:51:35.131] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:15:0)
[05:51:35.131] Timer tick, asking Buildbucket for the build status
[05:51:35.281] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:51:35.281] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:16:0) after 1m0s
[05:52:35.331] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:16:0)
[05:52:35.331] Timer tick, asking Buildbucket for the build status
[05:52:35.469] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:52:35.469] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:17:0) after 1m0s
[05:53:35.493] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:17:0)
[05:53:35.493] Timer tick, asking Buildbucket for the build status
[05:53:35.904] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:53:35.904] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:18:0) after 1m0s
[05:54:35.933] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:18:0)
[05:54:35.933] Timer tick, asking Buildbucket for the build status
[05:54:36.189] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:54:36.189] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:19:0) after 1m0s
[05:55:36.214] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:19:0)
[05:55:36.214] Timer tick, asking Buildbucket for the build status
[05:55:36.303] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:55:36.303] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:20:0) after 1m0s
[05:56:36.351] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:20:0)
[05:56:36.351] Timer tick, asking Buildbucket for the build status
[05:56:36.434] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:56:36.434] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:21:0) after 1m0s
[05:57:36.454] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:21:0)
[05:57:36.454] Timer tick, asking Buildbucket for the build status
[05:57:36.759] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:57:36.759] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:22:0) after 1m0s
[05:58:36.810] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:22:0)
[05:58:36.810] Timer tick, asking Buildbucket for the build status
[05:58:37.179] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:58:37.179] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:23:0) after 1m0s
[05:59:37.229] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:23:0)
[05:59:37.229] Timer tick, asking Buildbucket for the build status
[05:59:38.460] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[05:59:38.460] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:24:0) after 1m0s
[06:00:38.478] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:24:0)
[06:00:38.478] Timer tick, asking Buildbucket for the build status
[06:00:38.639] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:00:38.639] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:25:0) after 1m0s
[06:01:38.693] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:25:0)
[06:01:38.693] Timer tick, asking Buildbucket for the build status
[06:01:38.826] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:01:38.826] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:26:0) after 1m0s
[06:02:38.852] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:26:0)
[06:02:38.852] Timer tick, asking Buildbucket for the build status
[06:02:38.973] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:02:38.973] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:27:0) after 1m0s
[06:03:39.038] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:27:0)
[06:03:39.038] Timer tick, asking Buildbucket for the build status
[06:03:39.255] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:03:39.255] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:28:0) after 1m0s
[06:04:39.275] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:28:0)
[06:04:39.275] Timer tick, asking Buildbucket for the build status
[06:04:39.390] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:04:39.390] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:29:0) after 1m0s
[06:05:39.414] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:29:0)
[06:05:39.414] Timer tick, asking Buildbucket for the build status
[06:05:39.897] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:05:39.897] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:30:0) after 1m0s
[06:06:39.954] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:30:0)
[06:06:39.954] Timer tick, asking Buildbucket for the build status
[06:06:40.103] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:06:40.103] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:31:0) after 1m0s
[06:07:40.210] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:31:0)
[06:07:40.210] Timer tick, asking Buildbucket for the build status
[06:07:40.694] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:07:40.694] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:32:0) after 1m0s
[06:08:40.743] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:32:0)
[06:08:40.743] Timer tick, asking Buildbucket for the build status
[06:08:41.255] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:08:41.255] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:33:0) after 1m0s
[06:09:41.274] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:33:0)
[06:09:41.274] Timer tick, asking Buildbucket for the build status
[06:09:41.438] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:09:41.438] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:34:0) after 1m0s
[06:10:41.461] Handling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:34:0)
[06:10:41.461] Timer tick, asking Buildbucket for the build status
[06:10:43.870] Build 8890406886871293760: status "STARTED", result "", failure_reason "", cancelation_reason ""
[06:10:43.871] Scheduling timer "check-buildbucket-build-status" (infra/Build From Tarball:9055836949015347456:35:0) after 1m0s
[06:11:36.678] Received PubSub notification, asking Buildbucket for the build status
[06:11:36.747] Build 8890406886871293760: status "COMPLETED", result "FAILURE", failure_reason "BUILD_FAILURE", cancelation_reason ""
[06:11:36.747] Buildbucket build:
{
"build": {
"bucket": "luci.infra.cron",
"canary_preference": "PROD",
"completed_ts": "1579846296306135",
"created_by": "project:infra",
"created_ts": "1579844311797578",
"failure_reason": "BUILD_FAILURE",
"id": "8890406886871293760",
"parameters_json": "{\"builder_name\": \"Build From Tarball\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"buildbucket\": {\"properties\": {\"version\": \"81.0.4035.5\"}, \"tags\": [\"parent_buildername:publish_tarball\", \"user_agent:recipe\"]}, \"id\": \"5c53e18d-8701-4c4b-b72c-4b58bc52cc23\", \"title\": \"publish_tarball/0\"}]}, \"version\": \"81.0.4035.5\"}}",
"project": "infra",
"result": "FAILURE",
"result_details_json": "{\"error\": {\"message\": \"Step('Bootstrap gn.') (retcode: 1)\"}, \"properties\": {\"$gatekeeper\": {\"group\": \"chromium.infra.cron\"}, \"$recipe_engine/path\": {\"cache_dir\": \"/b/s/w/ir/cache\", \"temp_dir\": \"/b/s/w/ir/tmp/rt\"}, \"$recipe_engine/runtime\": {\"is_experimental\": false, \"is_luci\": true}, \"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"buildbucket\": {\"properties\": {\"version\": \"81.0.4035.5\"}, \"tags\": [\"parent_buildername:publish_tarball\", \"user_agent:recipe\"]}, \"id\": \"5c53e18d-8701-4c4b-b72c-4b58bc52cc23\", \"title\": \"publish_tarball/0\"}]}, \"bot_id\": \"luci-infra-cron-xenial-large-0-j08y\", \"buildername\": \"Build From Tarball\", \"path_config\": \"generic\", \"recipe\": \"build_from_tarball\", \"version\": \"81.0.4035.5\"}, \"swarming\": {\"bot_dimensions\": {\"builderless\": [\"1\"], \"caches\": [\"git\", \"vpython\"], \"cores\": [\"32\"], \"cpu\": [\"x86\", \"x86-64\", \"x86-64-Broadwell_GCE\", \"x86-64-avx2\"], \"gce\": [\"1\"], \"gcp\": [\"google.com:chromecompute\"], \"gpu\": [\"none\"], \"id\": [\"luci-infra-cron-xenial-large-0-j08y\"], \"image\": [\"chrome-xenial-20011900-be725824aad\"], \"inside_docker\": [\"0\"], \"kvm\": [\"1\"], \"locale\": [\"en_US.UTF-8\"], \"machine_type\": [\"n1-standard-32\"], \"os\": [\"Linux\", \"Ubuntu\", \"Ubuntu-16.04\"], \"pool\": [\"luci.infra.cron\"], \"python\": [\"2.7.12\"], \"server_version\": [\"4792-2014df3\"], \"ssd\": [\"0\"], \"zone\": [\"us\", \"us-east\", \"us-east1\", \"us-east1-b\"]}}, \"ui\": {\"info\": \"Step('Bootstrap gn.') (retcode: 1)\"}}",
"service_account": "chromium-tarball-builder@chops-service-accounts.iam.gserviceaccount.com",
"started_ts": "1579844627294279",
"status": "COMPLETED",
"status_changed_ts": "1579844627655532",
"tags": [
"builder:Build From Tarball",
"parent_buildername:publish_tarball",
"scheduler_invocation_id:9055836949015347456",
"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/8890406886871293760/+/annotations",
"swarming_tag:luci_project:infra",
"swarming_tag:os:Linux",
"swarming_tag:recipe_name:build_from_tarball",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/infra/infra",
"swarming_task_id:49eee0a4faa89b10",
"user_agent:luci-scheduler",
"user_agent:recipe"
],
"updated_ts": "1579846296364676",
"url": "https://ci.chromium.org/b/8890406886871293760",
"utcnow_ts": "1579846296738972"
}
}
[06:11:36.747] Invocation finished in 33m6.377989418s with status FAILED