[18:41:06.443] New invocation is queued and will start shortly
[18:41:07.710] Starting the invocation (attempt 1)
[18:41:07.755] Preparing PubSub topic for "https://cr-buildbucket.appspot.com"
[18:41:07.755] PubSub topic is "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
[18:41:07.755] Buildbucket request:
{
"bucket": "luci.celab.ci",
"client_operation_id": "9073272926537258112",
"parameters_json": "{\"builder_name\":\"Linux\",\"properties\":{\"$recipe_engine/scheduler\":{\"hostname\":\"luci-scheduler.appspot.com\",\"triggers\":[{\"gitiles\":{\"ref\":\"refs/heads/master\",\"repo\":\"https://chromium.googlesource.com/enterprise/cel.git\",\"revision\":\"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"},\"id\":\"https://chromium.googlesource.com/enterprise/cel.git/+/refs/heads/master@3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\",\"title\":\"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\",\"url\":\"https://chromium.googlesource.com/enterprise/cel.git/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}]},\"branch\":\"refs/heads/master\",\"repository\":\"https://chromium.googlesource.com/enterprise/cel.git\",\"revision\":\"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}}",
"pubsub_callback": {
"auth_token": "...",
"topic": "projects/luci-scheduler/topics/scheduler.buildbucket.cr-buildbucket~appspot.gserviceaccount.com"
},
"tags": [
"builder:Linux",
"scheduler_invocation_id:9073272926537258112",
"scheduler_job_id:celab/Linux",
"user_agent:luci-scheduler",
"buildset:commit/git/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac",
"buildset:commit/gitiles/chromium.googlesource.com/enterprise/cel/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac",
"gitiles_ref:refs/heads/master"
]
}
[18:41:09.336] Buildbucket response:
{
"build": {
"bucket": "luci.celab.ci",
"canary_preference": "PROD",
"created_by": "project:celab",
"created_ts": "1563216067902953",
"id": "8907842864341713168",
"parameters_json": "{\"builder_name\": \"Linux\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/enterprise/cel.git\", \"revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}, \"id\": \"https://chromium.googlesource.com/enterprise/cel.git/+/refs/heads/master@3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"title\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"url\": \"https://chromium.googlesource.com/enterprise/cel.git/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}]}, \"branch\": \"refs/heads/master\", \"repository\": \"https://chromium.googlesource.com/enterprise/cel.git\", \"revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}}",
"project": "celab",
"result_details_json": "{\"properties\": {}}",
"service_account": "celab-ci-builder@chops-service-accounts.iam.gserviceaccount.com",
"status": "SCHEDULED",
"status_changed_ts": "1563216068684336",
"tags": [
"builder:Linux",
"buildset:commit/git/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac",
"buildset:commit/gitiles/chromium.googlesource.com/enterprise/cel/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac",
"gitiles_ref:refs/heads/master",
"scheduler_invocation_id:9073272926537258112",
"scheduler_job_id:celab/Linux",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:log_location:logdog://logs.chromium.org/celab/buildbucket/cr-buildbucket.appspot.com/8907842864341713168/+/annotations",
"swarming_tag:luci_project:celab",
"swarming_tag:recipe_name:celab",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/chromium/tools/build",
"swarming_task_id:",
"user_agent:luci-scheduler"
],
"updated_ts": "1563216068684443",
"url": "https://ci.chromium.org/b/8907842864341713168",
"utcnow_ts": "1563216069327031"
}
}
[18:41:09.336] Task URL: https://ci.chromium.org/b/8907842864341713168
[18:41:09.336] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:2:0) after 1m0s
[18:41:22.268] Received PubSub notification, asking Buildbucket for the build status
[18:41:22.344] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:42:09.402] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:2:0)
[18:42:09.402] Timer tick, asking Buildbucket for the build status
[18:42:09.554] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:42:09.554] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:4:0) after 1m0s
[18:43:09.593] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:4:0)
[18:43:09.593] Timer tick, asking Buildbucket for the build status
[18:43:09.750] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:43:09.750] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:5:0) after 1m0s
[18:44:09.817] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:5:0)
[18:44:09.817] Timer tick, asking Buildbucket for the build status
[18:44:10.105] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:44:10.105] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:6:0) after 1m0s
[18:45:10.127] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:6:0)
[18:45:10.127] Timer tick, asking Buildbucket for the build status
[18:45:10.488] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:45:10.488] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:7:0) after 1m0s
[18:46:10.494] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:7:0)
[18:46:10.494] Timer tick, asking Buildbucket for the build status
[18:46:10.706] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:46:10.706] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:8:0) after 1m0s
[18:47:10.777] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:8:0)
[18:47:10.777] Timer tick, asking Buildbucket for the build status
[18:47:10.888] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:47:10.888] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:9:0) after 1m0s
[18:48:10.949] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:9:0)
[18:48:10.949] Timer tick, asking Buildbucket for the build status
[18:48:11.540] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:48:11.540] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:10:0) after 1m0s
[18:49:11.630] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:10:0)
[18:49:11.630] Timer tick, asking Buildbucket for the build status
[18:49:11.808] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:49:11.808] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:11:0) after 1m0s
[18:50:11.861] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:11:0)
[18:50:11.861] Timer tick, asking Buildbucket for the build status
[18:50:12.268] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:50:12.268] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:12:0) after 1m0s
[18:51:12.302] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:12:0)
[18:51:12.302] Timer tick, asking Buildbucket for the build status
[18:51:12.401] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:51:12.401] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:13:0) after 1m0s
[18:52:12.382] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:13:0)
[18:52:12.382] Timer tick, asking Buildbucket for the build status
[18:52:12.521] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:52:12.521] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:14:0) after 1m0s
[18:53:12.566] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:14:0)
[18:53:12.566] Timer tick, asking Buildbucket for the build status
[18:53:12.701] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:53:12.701] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:15:0) after 1m0s
[18:54:12.761] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:15:0)
[18:54:12.761] Timer tick, asking Buildbucket for the build status
[18:54:12.886] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:54:12.886] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:16:0) after 1m0s
[18:55:12.976] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:16:0)
[18:55:12.976] Timer tick, asking Buildbucket for the build status
[18:55:13.148] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:55:13.149] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:17:0) after 1m0s
[18:56:13.193] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:17:0)
[18:56:13.194] Timer tick, asking Buildbucket for the build status
[18:56:16.777] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:56:16.777] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:18:0) after 1m0s
[18:57:16.801] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:18:0)
[18:57:16.801] Timer tick, asking Buildbucket for the build status
[18:57:16.985] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:57:16.986] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:19:0) after 1m0s
[18:58:17.073] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:19:0)
[18:58:17.073] Timer tick, asking Buildbucket for the build status
[18:58:17.173] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:58:17.174] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:20:0) after 1m0s
[18:59:17.202] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:20:0)
[18:59:17.202] Timer tick, asking Buildbucket for the build status
[18:59:17.693] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[18:59:17.693] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:21:0) after 1m0s
[19:00:17.756] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:21:0)
[19:00:17.756] Timer tick, asking Buildbucket for the build status
[19:00:17.925] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:00:17.925] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:22:0) after 1m0s
[19:01:17.986] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:22:0)
[19:01:17.986] Timer tick, asking Buildbucket for the build status
[19:01:18.238] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:01:18.238] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:23:0) after 1m0s
[19:02:18.260] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:23:0)
[19:02:18.260] Timer tick, asking Buildbucket for the build status
[19:02:18.389] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:02:18.389] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:24:0) after 1m0s
[19:03:18.417] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:24:0)
[19:03:18.417] Timer tick, asking Buildbucket for the build status
[19:03:18.595] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:03:18.595] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:25:0) after 1m0s
[19:04:18.619] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:25:0)
[19:04:18.619] Timer tick, asking Buildbucket for the build status
[19:04:18.817] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:04:18.817] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:26:0) after 1m0s
[19:05:18.849] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:26:0)
[19:05:18.849] Timer tick, asking Buildbucket for the build status
[19:05:18.940] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:05:18.940] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:27:0) after 1m0s
[19:06:19.010] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:27:0)
[19:06:19.010] Timer tick, asking Buildbucket for the build status
[19:06:19.561] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:06:19.561] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:28:0) after 1m0s
[19:07:19.568] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:28:0)
[19:07:19.568] Timer tick, asking Buildbucket for the build status
[19:07:19.711] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:07:19.711] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:29:0) after 1m0s
[19:08:19.745] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:29:0)
[19:08:19.745] Timer tick, asking Buildbucket for the build status
[19:08:20.022] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:08:20.022] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:30:0) after 1m0s
[19:09:20.030] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:30:0)
[19:09:20.030] Timer tick, asking Buildbucket for the build status
[19:09:20.259] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:09:20.260] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:31:0) after 1m0s
[19:10:20.284] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:31:0)
[19:10:20.284] Timer tick, asking Buildbucket for the build status
[19:10:20.547] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:10:20.547] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:32:0) after 1m0s
[19:11:20.569] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:32:0)
[19:11:20.569] Timer tick, asking Buildbucket for the build status
[19:11:20.694] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:11:20.694] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:33:0) after 1m0s
[19:12:20.732] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:33:0)
[19:12:20.732] Timer tick, asking Buildbucket for the build status
[19:12:21.241] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:12:21.241] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:34:0) after 1m0s
[19:13:21.302] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:34:0)
[19:13:21.302] Timer tick, asking Buildbucket for the build status
[19:13:21.477] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:13:21.477] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:35:0) after 1m0s
[19:14:21.505] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:35:0)
[19:14:21.505] Timer tick, asking Buildbucket for the build status
[19:14:21.843] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:14:21.843] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:36:0) after 1m0s
[19:15:21.944] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:36:0)
[19:15:21.944] Timer tick, asking Buildbucket for the build status
[19:15:22.309] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:15:22.309] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:37:0) after 1m0s
[19:16:22.373] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:37:0)
[19:16:22.373] Timer tick, asking Buildbucket for the build status
[19:16:22.709] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:16:22.709] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:38:0) after 1m0s
[19:17:22.750] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:38:0)
[19:17:22.750] Timer tick, asking Buildbucket for the build status
[19:17:23.124] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:17:23.124] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:39:0) after 1m0s
[19:18:23.147] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:39:0)
[19:18:23.147] Timer tick, asking Buildbucket for the build status
[19:18:23.344] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:18:23.344] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:40:0) after 1m0s
[19:19:23.405] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:40:0)
[19:19:23.405] Timer tick, asking Buildbucket for the build status
[19:19:23.598] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:19:23.598] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:41:0) after 1m0s
[19:20:23.619] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:41:0)
[19:20:23.619] Timer tick, asking Buildbucket for the build status
[19:20:23.753] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:20:23.753] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:42:0) after 1m0s
[19:21:23.785] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:42:0)
[19:21:23.785] Timer tick, asking Buildbucket for the build status
[19:21:23.887] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:21:23.887] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:43:0) after 1m0s
[19:22:23.914] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:43:0)
[19:22:23.914] Timer tick, asking Buildbucket for the build status
[19:22:24.153] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:22:24.153] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:44:0) after 1m0s
[19:23:24.182] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:44:0)
[19:23:24.182] Timer tick, asking Buildbucket for the build status
[19:23:24.287] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:23:24.287] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:45:0) after 1m0s
[19:24:24.327] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:45:0)
[19:24:24.327] Timer tick, asking Buildbucket for the build status
[19:24:24.503] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:24:24.503] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:46:0) after 1m0s
[19:25:24.606] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:46:0)
[19:25:24.606] Timer tick, asking Buildbucket for the build status
[19:25:25.526] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:25:25.526] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:47:0) after 1m0s
[19:26:25.591] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:47:0)
[19:26:25.591] Timer tick, asking Buildbucket for the build status
[19:26:25.811] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:26:25.811] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:48:0) after 1m0s
[19:27:25.865] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:48:0)
[19:27:25.865] Timer tick, asking Buildbucket for the build status
[19:27:26.141] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:27:26.141] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:49:0) after 1m0s
[19:28:26.272] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:49:0)
[19:28:26.272] Timer tick, asking Buildbucket for the build status
[19:28:26.387] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:28:26.387] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:50:0) after 1m0s
[19:29:26.478] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:50:0)
[19:29:26.478] Timer tick, asking Buildbucket for the build status
[19:29:26.568] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:29:26.568] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:51:0) after 1m0s
[19:30:26.684] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:51:0)
[19:30:26.684] Timer tick, asking Buildbucket for the build status
[19:30:26.836] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:30:26.836] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:52:0) after 1m0s
[19:31:26.880] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:52:0)
[19:31:26.880] Timer tick, asking Buildbucket for the build status
[19:31:27.106] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:31:27.106] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:53:0) after 1m0s
[19:32:27.126] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:53:0)
[19:32:27.126] Timer tick, asking Buildbucket for the build status
[19:32:27.236] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:32:27.236] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:54:0) after 1m0s
[19:33:27.267] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:54:0)
[19:33:27.267] Timer tick, asking Buildbucket for the build status
[19:33:28.071] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:33:28.071] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:55:0) after 1m0s
[19:34:28.217] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:55:0)
[19:34:28.217] Timer tick, asking Buildbucket for the build status
[19:34:28.366] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:34:28.366] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:56:0) after 1m0s
[19:35:28.456] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:56:0)
[19:35:28.456] Timer tick, asking Buildbucket for the build status
[19:35:28.859] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:35:28.859] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:57:0) after 1m0s
[19:36:28.897] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:57:0)
[19:36:28.897] Timer tick, asking Buildbucket for the build status
[19:36:28.971] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:36:28.971] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:58:0) after 1m0s
[19:37:29.036] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:58:0)
[19:37:29.036] Timer tick, asking Buildbucket for the build status
[19:37:30.304] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:37:30.304] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:59:0) after 1m0s
[19:38:30.331] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:59:0)
[19:38:30.331] Timer tick, asking Buildbucket for the build status
[19:38:30.442] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:38:30.442] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:60:0) after 1m0s
[19:39:30.473] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:60:0)
[19:39:30.473] Timer tick, asking Buildbucket for the build status
[19:39:30.686] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:39:30.686] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:61:0) after 1m0s
[19:40:30.775] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:61:0)
[19:40:30.775] Timer tick, asking Buildbucket for the build status
[19:40:31.860] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:40:31.860] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:62:0) after 1m0s
[19:41:31.888] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:62:0)
[19:41:31.888] Timer tick, asking Buildbucket for the build status
[19:41:31.959] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:41:31.959] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:63:0) after 1m0s
[19:42:32.005] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:63:0)
[19:42:32.005] Timer tick, asking Buildbucket for the build status
[19:42:32.128] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:42:32.128] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:64:0) after 1m0s
[19:43:32.156] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:64:0)
[19:43:32.157] Timer tick, asking Buildbucket for the build status
[19:43:32.415] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:43:32.415] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:65:0) after 1m0s
[19:44:32.469] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:65:0)
[19:44:32.469] Timer tick, asking Buildbucket for the build status
[19:44:32.652] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:44:32.652] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:66:0) after 1m0s
[19:45:32.733] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:66:0)
[19:45:32.733] Timer tick, asking Buildbucket for the build status
[19:45:33.230] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:45:33.230] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:67:0) after 1m0s
[19:46:33.384] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:67:0)
[19:46:33.384] Timer tick, asking Buildbucket for the build status
[19:46:33.669] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:46:33.669] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:68:0) after 1m0s
[19:47:33.849] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:68:0)
[19:47:33.849] Timer tick, asking Buildbucket for the build status
[19:47:33.931] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:47:33.931] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:69:0) after 1m0s
[19:48:34.074] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:69:0)
[19:48:34.074] Timer tick, asking Buildbucket for the build status
[19:48:34.240] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:48:34.240] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:70:0) after 1m0s
[19:49:34.295] Handling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:70:0)
[19:49:34.295] Timer tick, asking Buildbucket for the build status
[19:49:34.455] Build 8907842864341713168: status "STARTED", result "", failure_reason "", cancelation_reason ""
[19:49:34.455] Scheduling timer "check-buildbucket-build-status" (celab/Linux:9073272926537258112:71:0) after 1m0s
[19:49:48.168] Received PubSub notification, asking Buildbucket for the build status
[19:49:48.288] Build 8907842864341713168: status "COMPLETED", result "FAILURE", failure_reason "BUILD_FAILURE", cancelation_reason ""
[19:49:48.288] Buildbucket build:
{
"build": {
"bucket": "luci.celab.ci",
"canary_preference": "PROD",
"completed_ts": "1563220187611177",
"created_by": "project:celab",
"created_ts": "1563216067902953",
"failure_reason": "BUILD_FAILURE",
"id": "8907842864341713168",
"parameters_json": "{\"builder_name\": \"Linux\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler.appspot.com\", \"triggers\": [{\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/enterprise/cel.git\", \"revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}, \"id\": \"https://chromium.googlesource.com/enterprise/cel.git/+/refs/heads/master@3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"title\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"url\": \"https://chromium.googlesource.com/enterprise/cel.git/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}]}, \"branch\": \"refs/heads/master\", \"repository\": \"https://chromium.googlesource.com/enterprise/cel.git\", \"revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}}",
"project": "celab",
"result": "FAILURE",
"result_details_json": "{\"error\": {\"message\": \"Step('run all tests') (retcode: 1)\"}, \"properties\": {\"$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/enterprise/cel.git\", \"revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}, \"id\": \"https://chromium.googlesource.com/enterprise/cel.git/+/refs/heads/master@3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"title\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"url\": \"https://chromium.googlesource.com/enterprise/cel.git/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\"}]}, \"bot_id\": \"luci-flex-ci-xenial-0-jvz0\", \"branch\": \"refs/heads/master\", \"buildername\": \"Linux\", \"got_revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"path_config\": \"generic\", \"pool_name\": \"celab-ci\", \"pool_size\": 5.0, \"recipe\": \"celab\", \"repository\": \"https://chromium.googlesource.com/enterprise/cel.git\", \"revision\": \"3c42cc59ec4f93537e3d3660d5b8336d8304f9ac\", \"target_cpu\": \"x64\", \"tests\": \"*\"}, \"ui\": {\"info\": \"Step('run all tests') (retcode: 1)\"}}",
"service_account": "celab-ci-builder@chops-service-accounts.iam.gserviceaccount.com",
"started_ts": "1563216081480312",
"status": "COMPLETED",
"status_changed_ts": "1563216068684336",
"tags": [
"builder:Linux",
"buildset:commit/git/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac",
"buildset:commit/gitiles/chromium.googlesource.com/enterprise/cel/+/3c42cc59ec4f93537e3d3660d5b8336d8304f9ac",
"gitiles_ref:refs/heads/master",
"scheduler_invocation_id:9073272926537258112",
"scheduler_job_id:celab/Linux",
"swarming_hostname:chromium-swarm.appspot.com",
"swarming_tag:log_location:logdog://logs.chromium.org/celab/buildbucket/cr-buildbucket.appspot.com/8907842864341713168/+/annotations",
"swarming_tag:luci_project:celab",
"swarming_tag:recipe_name:celab",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/chromium/tools/build",
"swarming_task_id:460fc1cd491b6010",
"user_agent:luci-scheduler"
],
"updated_ts": "1563220187785077",
"url": "https://ci.chromium.org/b/8907842864341713168",
"utcnow_ts": "1563220188277490"
}
}
[19:49:48.288] Invocation finished in 1h8m41.86250556s with status FAILED