[11:26:47.407] New invocation is queued and will start shortly
[11:26:48.619] Starting the invocation (attempt 1)
[11:26:48.711] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[11:26:48.712] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[11:26:48.712] Buildbucket request:
{
"bucket": "luci.nacl.toolchain",
"client_operation_id": "9021931771465400464",
"parameters_json": "{\"builder_name\":\"linux-pnacl-x86_64-tests-x86_32\",\"properties\":{\"$recipe_engine/scheduler\":{\"hostname\":\"luci-scheduler.appspot.com\",\"triggers\":[{\"gitiles\":{\"ref\":\"refs/heads/master\",\"repo\":\"https://chromium.googlesource.com/native_client/src/native_client.git\",\"revision\":\"952e81813a66902714b68f34b51073c5d1ba6c94\"},\"id\":\"https://chromium.googlesource.com/native_client/src/native_client.git/+/refs/heads/master@952e81813a66902714b68f34b51073c5d1ba6c94\",\"title\":\"952e81813a66902714b68f34b51073c5d1ba6c94\",\"url\":\"https://chromium.googlesource.com/native_client/src/native_client.git/+/952e81813a66902714b68f34b51073c5d1ba6c94\"}]},\"branch\":\"refs/heads/master\",\"repository\":\"https://chromium.googlesource.com/native_client/src/native_client.git\",\"revision\":\"952e81813a66902714b68f34b51073c5d1ba6c94\"}}",
"pubsub_callback": {
"auth_token": "...",
"topic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
},
"tags": [
"builder:linux-pnacl-x86_64-tests-x86_32",
"scheduler_invocation_id:9021931771465400464",
"scheduler_job_id:nacl/linux-pnacl-x86_64-tests-x86_32",
"user_agent:luci-scheduler",
"buildset:commit/git/952e81813a66902714b68f34b51073c5d1ba6c94",
"buildset:commit/gitiles/chromium.googlesource.com/native_client/src/native_client/+/952e81813a66902714b68f34b51073c5d1ba6c94",
"gitiles_ref:refs/heads/master"
]
}
[11:26:49.851] Buildbucket response:
{
"build": {
"bucket": "luci.nacl.toolchain",
"canary_preference": "PROD",
"created_by": "project:nacl",
"created_ts": "1612178808834935",
"id": "8856501709306296800",
"parameters_json": "{\"builder_name\": \"linux-pnacl-x86_64-tests-x86_32\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/native_client/src/native_client.git\", \"revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\"}, \"id\": \"https://chromium.googlesource.com/native_client/src/native_client.git/+/refs/heads/master@952e81813a66902714b68f34b51073c5d1ba6c94\", \"title\": \"952e81813a66902714b68f34b51073c5d1ba6c94\", \"url\": \"https://chromium.googlesource.com/native_client/src/native_client.git/+/952e81813a66902714b68f34b51073c5d1ba6c94\"}]}, \"branch\": \"refs/heads/master\", \"repository\": \"https://chromium.googlesource.com/native_client/src/native_client.git\", \"revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\"}}",
"project": "nacl",
"result_details_json": "{\"properties\": {}}",
"service_account": "nacl-toolchain-builder@chops-service-accounts.iam.gserviceaccount.com",
"status": "SCHEDULED",
"status_changed_ts": "1612178809505086",
"tags": [
"build_address:luci.nacl.toolchain/linux-pnacl-x86_64-tests-x86_32/5177",
"builder:linux-pnacl-x86_64-tests-x86_32",
"buildset:commit/git/952e81813a66902714b68f34b51073c5d1ba6c94",
"buildset:commit/gitiles/chromium.googlesource.com/native_client/src/native_client/+/952e81813a66902714b68f34b51073c5d1ba6c94",
"gitiles_ref:refs/heads/master",
"scheduler_invocation_id:9021931771465400464",
"scheduler_job_id:nacl/linux-pnacl-x86_64-tests-x86_32",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:log_location:logdog://logs.chromium.org/nacl/buildbucket/cr-buildbucket.appspot.com/8856501709306296800/+/annotations",
"swarming_tag:luci_project:nacl",
"swarming_tag:recipe_name:nacl",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/chromium/tools/build",
"swarming_task_id:",
"user_agent:luci-scheduler"
],
"updated_ts": "1612178809505229",
"url": "https://ci.chromium.org/b/8856501709306296800",
"utcnow_ts": "1612178809835607"
}
}
[11:26:49.851] Task URL: https://ci.chromium.org/b/8856501709306296800
[11:26:49.851] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:2:0) after 1m0s
[11:27:06.431] Received PubSub notification, asking Buildbucket for the build status
[11:27:06.842] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:27:50.316] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:2:0)
[11:27:50.316] Timer tick, asking Buildbucket for the build status
[11:27:50.447] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:27:50.447] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:4:0) after 1m0s
[11:28:50.469] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:4:0)
[11:28:50.469] Timer tick, asking Buildbucket for the build status
[11:28:50.588] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:28:50.588] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:5:0) after 1m0s
[11:29:50.698] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:5:0)
[11:29:50.699] Timer tick, asking Buildbucket for the build status
[11:29:50.996] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:29:50.996] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:6:0) after 1m0s
[11:30:51.063] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:6:0)
[11:30:51.063] Timer tick, asking Buildbucket for the build status
[11:30:51.195] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:30:51.195] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:7:0) after 1m0s
[11:31:51.214] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:7:0)
[11:31:51.214] Timer tick, asking Buildbucket for the build status
[11:31:51.557] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:31:51.557] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:8:0) after 1m0s
[11:32:51.604] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:8:0)
[11:32:51.604] Timer tick, asking Buildbucket for the build status
[11:32:52.027] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:32:52.027] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:9:0) after 1m0s
[11:33:52.092] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:9:0)
[11:33:52.092] Timer tick, asking Buildbucket for the build status
[11:33:52.196] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:33:52.196] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:10:0) after 1m0s
[11:34:52.270] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:10:0)
[11:34:52.270] Timer tick, asking Buildbucket for the build status
[11:34:52.475] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:34:52.475] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:11:0) after 1m0s
[11:35:52.581] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:11:0)
[11:35:52.582] Timer tick, asking Buildbucket for the build status
[11:35:52.745] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:35:52.745] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:12:0) after 1m0s
[11:36:53.011] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:12:0)
[11:36:53.011] Timer tick, asking Buildbucket for the build status
[11:36:53.216] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:36:53.216] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:13:0) after 1m0s
[11:37:53.262] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:13:0)
[11:37:53.262] Timer tick, asking Buildbucket for the build status
[11:37:53.337] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:37:53.337] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:14:0) after 1m0s
[11:38:53.398] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:14:0)
[11:38:53.398] Timer tick, asking Buildbucket for the build status
[11:38:53.617] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:38:53.617] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:15:0) after 1m0s
[11:39:53.622] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:15:0)
[11:39:53.622] Timer tick, asking Buildbucket for the build status
[11:39:53.686] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:39:53.686] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:16:0) after 1m0s
[11:40:53.717] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:16:0)
[11:40:53.717] Timer tick, asking Buildbucket for the build status
[11:40:53.794] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:40:53.794] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:17:0) after 1m0s
[11:41:53.861] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:17:0)
[11:41:53.861] Timer tick, asking Buildbucket for the build status
[11:41:54.218] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:41:54.218] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:18:0) after 1m0s
[11:42:54.306] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:18:0)
[11:42:54.306] Timer tick, asking Buildbucket for the build status
[11:42:54.377] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:42:54.377] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:19:0) after 1m0s
[11:43:54.416] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:19:0)
[11:43:54.416] Timer tick, asking Buildbucket for the build status
[11:43:54.998] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:43:54.998] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:20:0) after 1m0s
[11:44:55.114] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:20:0)
[11:44:55.114] Timer tick, asking Buildbucket for the build status
[11:44:55.335] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:44:55.335] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:21:0) after 1m0s
[11:45:55.396] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:21:0)
[11:45:55.396] Timer tick, asking Buildbucket for the build status
[11:45:55.512] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:45:55.512] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:22:0) after 1m0s
[11:46:55.544] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:22:0)
[11:46:55.544] Timer tick, asking Buildbucket for the build status
[11:46:55.657] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:46:55.657] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:23:0) after 1m0s
[11:47:55.748] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:23:0)
[11:47:55.748] Timer tick, asking Buildbucket for the build status
[11:47:56.142] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:47:56.142] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:24:0) after 1m0s
[11:48:56.242] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:24:0)
[11:48:56.242] Timer tick, asking Buildbucket for the build status
[11:48:56.527] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:48:56.527] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:25:0) after 1m0s
[11:49:56.681] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:25:0)
[11:49:56.681] Timer tick, asking Buildbucket for the build status
[11:49:56.791] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:49:56.792] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:26:0) after 1m0s
[11:50:56.859] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:26:0)
[11:50:56.859] Timer tick, asking Buildbucket for the build status
[11:50:57.038] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:50:57.038] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:27:0) after 1m0s
[11:51:57.063] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:27:0)
[11:51:57.063] Timer tick, asking Buildbucket for the build status
[11:51:57.536] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:51:57.536] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:28:0) after 1m0s
[11:52:57.527] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:28:0)
[11:52:57.527] Timer tick, asking Buildbucket for the build status
[11:52:57.809] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:52:57.809] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:29:0) after 1m0s
[11:53:57.822] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:29:0)
[11:53:57.822] Timer tick, asking Buildbucket for the build status
[11:53:58.138] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:53:58.138] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:30:0) after 1m0s
[11:54:58.167] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:30:0)
[11:54:58.167] Timer tick, asking Buildbucket for the build status
[11:54:58.321] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:54:58.321] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:31:0) after 1m0s
[11:55:58.408] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:31:0)
[11:55:58.408] Timer tick, asking Buildbucket for the build status
[11:55:58.498] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:55:58.498] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:32:0) after 1m0s
[11:56:58.564] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:32:0)
[11:56:58.564] Timer tick, asking Buildbucket for the build status
[11:56:58.724] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:56:58.724] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:33:0) after 1m0s
[11:57:58.755] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:33:0)
[11:57:58.755] Timer tick, asking Buildbucket for the build status
[11:57:58.942] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:57:58.942] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:34:0) after 1m0s
[11:58:59.027] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:34:0)
[11:58:59.028] Timer tick, asking Buildbucket for the build status
[11:58:59.200] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:58:59.200] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:35:0) after 1m0s
[11:59:59.244] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:35:0)
[11:59:59.244] Timer tick, asking Buildbucket for the build status
[11:59:59.341] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[11:59:59.341] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:36:0) after 1m0s
[12:00:59.369] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:36:0)
[12:00:59.369] Timer tick, asking Buildbucket for the build status
[12:00:59.455] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:00:59.455] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:37:0) after 1m0s
[12:01:59.466] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:37:0)
[12:01:59.466] Timer tick, asking Buildbucket for the build status
[12:01:59.613] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:01:59.613] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:38:0) after 1m0s
[12:02:59.646] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:38:0)
[12:02:59.646] Timer tick, asking Buildbucket for the build status
[12:02:59.797] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:02:59.797] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:39:0) after 1m0s
[12:03:59.819] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:39:0)
[12:03:59.819] Timer tick, asking Buildbucket for the build status
[12:04:00.115] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:04:00.115] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:40:0) after 1m0s
[12:05:00.145] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:40:0)
[12:05:00.145] Timer tick, asking Buildbucket for the build status
[12:05:00.297] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:05:00.297] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:41:0) after 1m0s
[12:06:00.363] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:41:0)
[12:06:00.363] Timer tick, asking Buildbucket for the build status
[12:06:00.451] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:06:00.451] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:42:0) after 1m0s
[12:07:00.467] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:42:0)
[12:07:00.467] Timer tick, asking Buildbucket for the build status
[12:07:00.581] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:07:00.581] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:43:0) after 1m0s
[12:08:00.894] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:43:0)
[12:08:00.895] Timer tick, asking Buildbucket for the build status
[12:08:00.958] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:08:00.958] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:44:0) after 1m0s
[12:09:01.244] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:44:0)
[12:09:01.244] Timer tick, asking Buildbucket for the build status
[12:09:01.311] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:09:01.311] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:45:0) after 1m0s
[12:10:01.728] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:45:0)
[12:10:01.728] Timer tick, asking Buildbucket for the build status
[12:10:01.811] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:10:01.811] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:46:0) after 1m0s
[12:11:01.885] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:46:0)
[12:11:01.885] Timer tick, asking Buildbucket for the build status
[12:11:01.957] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:11:01.957] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:47:0) after 1m0s
[12:12:01.982] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:47:0)
[12:12:01.982] Timer tick, asking Buildbucket for the build status
[12:12:02.352] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:12:02.352] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:48:0) after 1m0s
[12:13:02.398] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:48:0)
[12:13:02.398] Timer tick, asking Buildbucket for the build status
[12:13:02.706] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:13:02.706] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:49:0) after 1m0s
[12:14:02.733] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:49:0)
[12:14:02.733] Timer tick, asking Buildbucket for the build status
[12:14:03.161] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:14:03.162] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:50:0) after 1m0s
[12:15:03.168] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:50:0)
[12:15:03.169] Timer tick, asking Buildbucket for the build status
[12:15:03.275] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:15:03.275] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:51:0) after 1m0s
[12:16:03.303] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:51:0)
[12:16:03.303] Timer tick, asking Buildbucket for the build status
[12:16:03.645] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:16:03.645] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:52:0) after 1m0s
[12:17:03.727] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:52:0)
[12:17:03.727] Timer tick, asking Buildbucket for the build status
[12:17:04.110] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:17:04.110] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:53:0) after 1m0s
[12:18:04.198] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:53:0)
[12:18:04.198] Timer tick, asking Buildbucket for the build status
[12:18:04.261] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:18:04.262] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:54:0) after 1m0s
[12:19:04.288] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:54:0)
[12:19:04.288] Timer tick, asking Buildbucket for the build status
[12:19:04.443] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:19:04.443] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:55:0) after 1m0s
[12:20:04.526] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:55:0)
[12:20:04.527] Timer tick, asking Buildbucket for the build status
[12:20:04.968] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:20:04.969] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:56:0) after 1m0s
[12:21:05.057] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:56:0)
[12:21:05.057] Timer tick, asking Buildbucket for the build status
[12:21:05.736] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:21:05.736] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:57:0) after 1m0s
[12:22:05.847] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:57:0)
[12:22:05.847] Timer tick, asking Buildbucket for the build status
[12:22:06.092] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:22:06.092] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:58:0) after 1m0s
[12:23:06.240] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:58:0)
[12:23:06.240] Timer tick, asking Buildbucket for the build status
[12:23:06.325] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:23:06.325] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:59:0) after 1m0s
[12:24:06.497] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:59:0)
[12:24:06.498] Timer tick, asking Buildbucket for the build status
[12:24:06.580] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:24:06.580] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:60:0) after 1m0s
[12:25:06.658] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:60:0)
[12:25:06.658] Timer tick, asking Buildbucket for the build status
[12:25:06.751] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:25:06.751] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:61:0) after 1m0s
[12:26:06.884] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:61:0)
[12:26:06.884] Timer tick, asking Buildbucket for the build status
[12:26:06.960] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:26:06.960] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:62:0) after 1m0s
[12:27:07.045] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:62:0)
[12:27:07.045] Timer tick, asking Buildbucket for the build status
[12:27:07.768] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:27:07.768] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:63:0) after 1m0s
[12:28:07.980] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:63:0)
[12:28:07.980] Timer tick, asking Buildbucket for the build status
[12:28:09.755] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:28:09.755] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:64:0) after 1m0s
[12:29:09.794] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:64:0)
[12:29:09.794] Timer tick, asking Buildbucket for the build status
[12:29:09.889] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:29:09.889] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:65:0) after 1m0s
[12:30:09.991] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:65:0)
[12:30:09.991] Timer tick, asking Buildbucket for the build status
[12:30:10.159] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:30:10.159] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:66:0) after 1m0s
[12:31:10.229] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:66:0)
[12:31:10.230] Timer tick, asking Buildbucket for the build status
[12:31:10.301] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:31:10.301] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:67:0) after 1m0s
[12:32:10.333] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:67:0)
[12:32:10.333] Timer tick, asking Buildbucket for the build status
[12:32:10.452] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:32:10.452] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:68:0) after 1m0s
[12:33:10.462] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:68:0)
[12:33:10.462] Timer tick, asking Buildbucket for the build status
[12:33:10.812] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:33:10.812] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:69:0) after 1m0s
[12:34:10.819] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:69:0)
[12:34:10.819] Timer tick, asking Buildbucket for the build status
[12:34:10.874] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:34:10.874] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:70:0) after 1m0s
[12:35:10.946] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:70:0)
[12:35:10.946] Timer tick, asking Buildbucket for the build status
[12:35:11.733] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:35:11.734] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:71:0) after 1m0s
[12:36:11.778] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:71:0)
[12:36:11.778] Timer tick, asking Buildbucket for the build status
[12:36:11.948] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:36:11.948] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:72:0) after 1m0s
[12:37:12.078] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:72:0)
[12:37:12.078] Timer tick, asking Buildbucket for the build status
[12:37:12.218] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:37:12.218] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:73:0) after 1m0s
[12:38:12.275] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:73:0)
[12:38:12.275] Timer tick, asking Buildbucket for the build status
[12:38:12.360] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:38:12.360] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:74:0) after 1m0s
[12:39:12.384] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:74:0)
[12:39:12.384] Timer tick, asking Buildbucket for the build status
[12:39:12.446] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:39:12.446] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:75:0) after 1m0s
[12:40:12.526] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:75:0)
[12:40:12.526] Timer tick, asking Buildbucket for the build status
[12:40:12.633] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:40:12.633] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:76:0) after 1m0s
[12:41:12.662] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:76:0)
[12:41:12.662] Timer tick, asking Buildbucket for the build status
[12:41:12.726] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:41:12.726] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:77:0) after 1m0s
[12:42:12.793] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:77:0)
[12:42:12.793] Timer tick, asking Buildbucket for the build status
[12:42:13.129] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:42:13.129] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:78:0) after 1m0s
[12:43:13.208] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:78:0)
[12:43:13.208] Timer tick, asking Buildbucket for the build status
[12:43:13.299] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:43:13.299] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:79:0) after 1m0s
[12:44:13.360] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:79:0)
[12:44:13.360] Timer tick, asking Buildbucket for the build status
[12:44:13.515] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:44:13.515] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:80:0) after 1m0s
[12:45:13.531] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:80:0)
[12:45:13.531] Timer tick, asking Buildbucket for the build status
[12:45:13.617] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:45:13.617] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:81:0) after 1m0s
[12:46:13.715] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:81:0)
[12:46:13.715] Timer tick, asking Buildbucket for the build status
[12:46:13.780] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:46:13.780] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:82:0) after 1m0s
[12:47:13.819] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:82:0)
[12:47:13.819] Timer tick, asking Buildbucket for the build status
[12:47:14.256] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:47:14.256] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:83:0) after 1m0s
[12:48:14.300] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:83:0)
[12:48:14.300] Timer tick, asking Buildbucket for the build status
[12:48:14.513] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:48:14.513] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:84:0) after 1m0s
[12:49:14.514] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:84:0)
[12:49:14.514] Timer tick, asking Buildbucket for the build status
[12:49:14.939] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:49:14.939] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:85:0) after 1m0s
[12:50:14.967] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:85:0)
[12:50:14.967] Timer tick, asking Buildbucket for the build status
[12:50:15.049] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:50:15.049] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:86:0) after 1m0s
[12:51:15.084] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:86:0)
[12:51:15.084] Timer tick, asking Buildbucket for the build status
[12:51:15.153] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:51:15.153] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:87:0) after 1m0s
[12:52:15.177] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:87:0)
[12:52:15.177] Timer tick, asking Buildbucket for the build status
[12:52:15.568] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:52:15.568] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:88:0) after 1m0s
[12:53:15.624] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:88:0)
[12:53:15.624] Timer tick, asking Buildbucket for the build status
[12:53:15.835] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:53:15.835] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:89:0) after 1m0s
[12:54:15.875] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:89:0)
[12:54:15.875] Timer tick, asking Buildbucket for the build status
[12:54:15.959] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:54:15.959] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:90:0) after 1m0s
[12:55:15.980] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:90:0)
[12:55:15.980] Timer tick, asking Buildbucket for the build status
[12:55:16.141] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:55:16.141] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:91:0) after 1m0s
[12:56:16.169] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:91:0)
[12:56:16.169] Timer tick, asking Buildbucket for the build status
[12:56:16.234] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:56:16.234] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:92:0) after 1m0s
[12:57:16.259] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:92:0)
[12:57:16.259] Timer tick, asking Buildbucket for the build status
[12:57:16.385] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:57:16.385] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:93:0) after 1m0s
[12:58:16.421] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:93:0)
[12:58:16.421] Timer tick, asking Buildbucket for the build status
[12:58:16.532] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:58:16.532] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:94:0) after 1m0s
[12:59:16.654] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:94:0)
[12:59:16.654] Timer tick, asking Buildbucket for the build status
[12:59:16.744] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[12:59:16.744] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:95:0) after 1m0s
[13:00:17.032] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:95:0)
[13:00:17.032] Timer tick, asking Buildbucket for the build status
[13:00:17.815] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:00:17.815] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:96:0) after 1m0s
[13:01:17.935] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:96:0)
[13:01:17.935] Timer tick, asking Buildbucket for the build status
[13:01:18.141] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:01:18.141] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:97:0) after 1m0s
[13:02:18.236] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:97:0)
[13:02:18.236] Timer tick, asking Buildbucket for the build status
[13:02:18.609] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:02:18.609] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:98:0) after 1m0s
[13:03:18.673] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:98:0)
[13:03:18.673] Timer tick, asking Buildbucket for the build status
[13:03:18.755] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:03:18.755] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:99:0) after 1m0s
[13:04:18.742] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:99:0)
[13:04:18.742] Timer tick, asking Buildbucket for the build status
[13:04:18.889] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:04:18.889] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:100:0) after 1m0s
[13:05:18.994] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:100:0)
[13:05:18.994] Timer tick, asking Buildbucket for the build status
[13:05:19.311] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:05:19.311] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:101:0) after 1m0s
[13:06:19.440] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:101:0)
[13:06:19.440] Timer tick, asking Buildbucket for the build status
[13:06:19.695] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:06:19.695] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:102:0) after 1m0s
[13:07:19.768] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:102:0)
[13:07:19.768] Timer tick, asking Buildbucket for the build status
[13:07:19.880] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:07:19.880] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:103:0) after 1m0s
[13:08:19.938] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:103:0)
[13:08:19.938] Timer tick, asking Buildbucket for the build status
[13:08:20.136] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:08:20.136] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:104:0) after 1m0s
[13:09:20.206] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:104:0)
[13:09:20.206] Timer tick, asking Buildbucket for the build status
[13:09:20.265] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:09:20.265] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:105:0) after 1m0s
[13:10:20.368] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:105:0)
[13:10:20.368] Timer tick, asking Buildbucket for the build status
[13:10:20.642] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:10:20.642] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:106:0) after 1m0s
[13:11:20.677] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:106:0)
[13:11:20.677] Timer tick, asking Buildbucket for the build status
[13:11:20.794] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:11:20.794] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:107:0) after 1m0s
[13:12:20.847] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:107:0)
[13:12:20.847] Timer tick, asking Buildbucket for the build status
[13:12:21.150] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:12:21.150] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:108:0) after 1m0s
[13:13:21.201] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:108:0)
[13:13:21.201] Timer tick, asking Buildbucket for the build status
[13:13:21.720] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:13:21.720] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:109:0) after 1m0s
[13:14:21.736] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:109:0)
[13:14:21.736] Timer tick, asking Buildbucket for the build status
[13:14:21.803] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:14:21.803] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:110:0) after 1m0s
[13:15:21.976] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:110:0)
[13:15:21.976] Timer tick, asking Buildbucket for the build status
[13:15:22.295] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:15:22.295] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:111:0) after 1m0s
[13:16:22.550] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:111:0)
[13:16:22.550] Timer tick, asking Buildbucket for the build status
[13:16:22.742] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:16:22.742] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:112:0) after 1m0s
[13:17:22.937] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:112:0)
[13:17:22.937] Timer tick, asking Buildbucket for the build status
[13:17:23.437] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:17:23.437] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:113:0) after 1m0s
[13:18:23.478] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:113:0)
[13:18:23.478] Timer tick, asking Buildbucket for the build status
[13:18:23.681] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:18:23.681] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:114:0) after 1m0s
[13:19:23.762] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:114:0)
[13:19:23.762] Timer tick, asking Buildbucket for the build status
[13:19:23.831] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:19:23.831] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:115:0) after 1m0s
[13:20:23.889] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:115:0)
[13:20:23.889] Timer tick, asking Buildbucket for the build status
[13:20:24.074] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:20:24.074] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:116:0) after 1m0s
[13:21:24.198] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:116:0)
[13:21:24.198] Timer tick, asking Buildbucket for the build status
[13:21:24.264] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:21:24.264] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:117:0) after 1m0s
[13:22:24.332] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:117:0)
[13:22:24.332] Timer tick, asking Buildbucket for the build status
[13:22:24.496] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:22:24.496] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:118:0) after 1m0s
[13:23:26.454] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:118:0)
[13:23:26.454] Timer tick, asking Buildbucket for the build status
[13:23:26.746] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:23:26.746] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:119:0) after 1m0s
[13:24:26.851] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:119:0)
[13:24:26.851] Timer tick, asking Buildbucket for the build status
[13:24:27.337] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:24:27.337] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:120:0) after 1m0s
[13:25:27.450] Handling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:120:0)
[13:25:27.450] Timer tick, asking Buildbucket for the build status
[13:25:27.786] Build 8856501709306296800: status "STARTED", result "", failure_reason "", cancelation_reason ""
[13:25:27.787] Scheduling timer "check-buildbucket-build-status" (nacl/linux-pnacl-x86_64-tests-x86_32:9021931771465400464:121:0) after 1m0s
[13:25:45.636] Received PubSub notification, asking Buildbucket for the build status
[13:25:45.749] Build 8856501709306296800: status "COMPLETED", result "FAILURE", failure_reason "BUILD_FAILURE", cancelation_reason ""
[13:25:45.750] Buildbucket build:
{
"build": {
"bucket": "luci.nacl.toolchain",
"canary_preference": "PROD",
"completed_ts": "1612185945255981",
"created_by": "project:nacl",
"created_ts": "1612178808834935",
"failure_reason": "BUILD_FAILURE",
"id": "8856501709306296800",
"parameters_json": "{\"builder_name\": \"linux-pnacl-x86_64-tests-x86_32\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/native_client/src/native_client.git\", \"revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\"}, \"id\": \"https://chromium.googlesource.com/native_client/src/native_client.git/+/refs/heads/master@952e81813a66902714b68f34b51073c5d1ba6c94\", \"title\": \"952e81813a66902714b68f34b51073c5d1ba6c94\", \"url\": \"https://chromium.googlesource.com/native_client/src/native_client.git/+/952e81813a66902714b68f34b51073c5d1ba6c94\"}]}, \"branch\": \"refs/heads/master\", \"repository\": \"https://chromium.googlesource.com/native_client/src/native_client.git\", \"revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\"}}",
"project": "nacl",
"result": "FAILURE",
"result_details_json": "{\"error\": {\"message\": \"Step('annotated steps') (retcode: 1)\"}, \"properties\": {\"$build/goma\": {\"enable_ats\": true, \"rpc_extra_params\": \"?prod\", \"server_host\": \"goma.chromium.org\"}, \"$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\": [{\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/native_client/src/native_client.git\", \"revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\"}, \"id\": \"https://chromium.googlesource.com/native_client/src/native_client.git/+/refs/heads/master@952e81813a66902714b68f34b51073c5d1ba6c94\", \"title\": \"952e81813a66902714b68f34b51073c5d1ba6c94\", \"url\": \"https://chromium.googlesource.com/native_client/src/native_client.git/+/952e81813a66902714b68f34b51073c5d1ba6c94\"}]}, \"bot_id\": \"luci-nacl-toolchain-xenial-2-jd8d\", \"branch\": \"refs/heads/master\", \"builder_group\": \"client.nacl.toolchain\", \"buildername\": \"linux-pnacl-x86_64-tests-x86_32\", \"buildnumber\": 5177, \"got_revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\", \"path_config\": \"generic\", \"recipe\": \"nacl\", \"repository\": \"https://chromium.googlesource.com/native_client/src/native_client.git\", \"revision\": \"952e81813a66902714b68f34b51073c5d1ba6c94\", \"slavetype\": \"BuilderTester\"}, \"swarming\": {\"bot_dimensions\": {\"cores\": [\"16\"], \"cpu\": [\"x86\", \"x86-64\", \"x86-64-Broadwell_GCE\", \"x86-64-avx2\"], \"gce\": [\"1\"], \"gcp\": [\"google.com:chromecompute\"], \"gpu\": [\"none\"], \"id\": [\"luci-nacl-toolchain-xenial-2-jd8d\"], \"image\": [\"chrome-xenial-21011100-9488e34e558\"], \"inside_docker\": [\"0\"], \"kvm\": [\"1\"], \"locale\": [\"en_US.UTF-8\"], \"machine_type\": [\"n1-standard-16\"], \"os\": [\"Linux\", \"Ubuntu\", \"Ubuntu-16\", \"Ubuntu-16.04\", \"Ubuntu-16.04.6\"], \"pool\": [\"luci.nacl.toolchain\"], \"python\": [\"2.7.12\"], \"server_version\": [\"5673-2413400\"], \"ssd\": [\"0\"], \"zone\": [\"us\", \"us-east\", \"us-east1\", \"us-east1-b\"]}}, \"ui\": {\"info\": \"Step('annotated steps') (retcode: 1)\"}}",
"service_account": "nacl-toolchain-builder@chops-service-accounts.iam.gserviceaccount.com",
"started_ts": "1612178825139897",
"status": "COMPLETED",
"status_changed_ts": "1612178825608210",
"tags": [
"build_address:luci.nacl.toolchain/linux-pnacl-x86_64-tests-x86_32/5177",
"builder:linux-pnacl-x86_64-tests-x86_32",
"buildset:commit/git/952e81813a66902714b68f34b51073c5d1ba6c94",
"buildset:commit/gitiles/chromium.googlesource.com/native_client/src/native_client/+/952e81813a66902714b68f34b51073c5d1ba6c94",
"gitiles_ref:refs/heads/master",
"scheduler_invocation_id:9021931771465400464",
"scheduler_job_id:nacl/linux-pnacl-x86_64-tests-x86_32",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:log_location:logdog://logs.chromium.org/nacl/buildbucket/cr-buildbucket.appspot.com/8856501709306296800/+/annotations",
"swarming_tag:luci_project:nacl",
"swarming_tag:os:Linux",
"swarming_tag:recipe_name:nacl",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/chromium/tools/build",
"swarming_task_id:517629ebf6d44610",
"user_agent:luci-scheduler"
],
"updated_ts": "1612185945334067",
"url": "https://ci.chromium.org/b/8856501709306296800",
"utcnow_ts": "1612185945726262"
}
}
[13:25:45.750] Invocation finished in 1h58m58.358627893s with status FAILED