[20:03:42.141] New invocation is queued and will start shortly
[20:03:43.302] Starting the invocation (attempt 1)
[20:03:43.341] Popped gitiles commit info from properties and tags
[20:03:43.341] Popped a tag as redundant: buildset:commit/git/08a960b11cbe6c08d428bf215daaf35ac8e09cc9
[20:03:43.341] Popped a tag as redundant: buildset:commit/gitiles/chromium.googlesource.com/infra/infra/+/08a960b11cbe6c08d428bf215daaf35ac8e09cc9
[20:03:43.341] Popped a tag as redundant: gitiles_ref:refs/heads/master
[20:03:43.341] Preparing PubSub topic for "https://cr-buildbucket-dev.appspot.com"
[20:03:43.341] PubSub topic is "projects/luci-scheduler-dev/topics/scheduler.buildbucket.cr-buildbucket-dev~appspot.gserviceaccount.com"
[20:03:43.341] Buildbucket request:
{
"requestId": "9018094177570482400",
"builder": {
"project": "infra",
"bucket": "ci",
"builder": "infra-continuous-win10-64"
},
"properties": {
"$recipe_engine/scheduler": {
"hostname": "luci-scheduler-dev.appspot.com",
"triggers": [
{
"gitiles": {
"ref": "refs/heads/master",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "47503212cf4e2ac3f379c08a979d93025ed448ff"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/master@47503212cf4e2ac3f379c08a979d93025ed448ff",
"title": "47503212cf4e2ac3f379c08a979d93025ed448ff",
"url": "https://chromium.googlesource.com/infra/infra/+/47503212cf4e2ac3f379c08a979d93025ed448ff"
},
{
"gitiles": {
"ref": "refs/heads/master",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "895b7bb4e15267d8c7bc342d6f66551819b06577"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/master@895b7bb4e15267d8c7bc342d6f66551819b06577",
"title": "895b7bb4e15267d8c7bc342d6f66551819b06577",
"url": "https://chromium.googlesource.com/infra/infra/+/895b7bb4e15267d8c7bc342d6f66551819b06577"
},
{
"gitiles": {
"ref": "refs/heads/master",
"repo": "https://chromium.googlesource.com/infra/infra",
"revision": "08a960b11cbe6c08d428bf215daaf35ac8e09cc9"
},
"id": "https://chromium.googlesource.com/infra/infra/+/refs/heads/master@08a960b11cbe6c08d428bf215daaf35ac8e09cc9",
"title": "08a960b11cbe6c08d428bf215daaf35ac8e09cc9",
"url": "https://chromium.googlesource.com/infra/infra/+/08a960b11cbe6c08d428bf215daaf35ac8e09cc9"
}
]
}
},
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "infra/infra",
"id": "08a960b11cbe6c08d428bf215daaf35ac8e09cc9",
"ref": "refs/heads/master"
},
"tags": [
{
"key": "scheduler_invocation_id",
"value": "9018094177570482400"
},
{
"key": "scheduler_job_id",
"value": "infra/infra-continuous-win10-64"
},
{
"key": "user_agent",
"value": "luci-scheduler-dev"
}
],
"notify": {
"pubsubTopic": "projects/luci-scheduler-dev/topics/scheduler.buildbucket.cr-buildbucket-dev~appspot.gserviceaccount.com"
}
}
[20:03:43.951] Scheduled build:
{
"id": "8852664115517437984",
"builder": {
"project": "infra",
"bucket": "ci",
"builder": "infra-continuous-win10-64"
},
"number": 18868,
"createdBy": "project:infra",
"createTime": "2021-03-15T20:03:43.467850Z",
"updateTime": "2021-03-15T20:03:43.885828Z",
"status": "SCHEDULED",
"input": {
"gitilesCommit": {
"host": "chromium.googlesource.com",
"project": "infra/infra",
"id": "08a960b11cbe6c08d428bf215daaf35ac8e09cc9",
"ref": "refs/heads/master"
}
}
}
[20:03:43.951] Task URL: https://cr-buildbucket-dev.appspot.com/build/8852664115517437984
[20:03:43.951] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:2:0) after 3m23s
[20:07:07.054] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:2:0)
[20:07:07.054] Timer tick, asking Buildbucket for the build status
[20:07:07.274] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:07:07.274] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:3:0) after 1m0s
[20:08:07.311] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:3:0)
[20:08:07.400] Build status: SCHEDULED
[20:08:07.400] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:4:0) after 3m35s
[20:11:42.417] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:4:0)
[20:11:42.417] Timer tick, asking Buildbucket for the build status
[20:11:42.503] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:11:42.503] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:5:0) after 1m0s
[20:12:42.593] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:5:0)
[20:12:42.627] Build status: SCHEDULED
[20:12:42.627] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:6:0) after 3m42s
[20:16:24.707] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:6:0)
[20:16:24.707] Timer tick, asking Buildbucket for the build status
[20:16:24.787] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:16:24.787] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:7:0) after 1m0s
[20:17:24.809] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:7:0)
[20:17:24.809] Timer tick, asking Buildbucket for the build status
[20:17:24.894] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:17:24.894] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:8:0) after 1m0s
[20:18:24.996] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:8:0)
[20:18:24.996] Timer tick, asking Buildbucket for the build status
[20:18:25.095] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:18:25.095] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:9:0) after 1m0s
[20:19:25.132] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:9:0)
[20:19:25.224] Build status: SCHEDULED
[20:19:25.224] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:10:0) after 8m2s
[20:27:27.284] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:10:0)
[20:27:27.312] Build status: SCHEDULED
[20:27:27.312] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:11:0) after 2m30s
[20:29:57.384] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:11:0)
[20:29:57.426] Build status: SCHEDULED
[20:29:57.426] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:12:0) after 6m42s
[20:36:39.483] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:12:0)
[20:36:39.594] Build status: SCHEDULED
[20:36:39.594] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:13:0) after 7m20s
[20:43:59.695] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:13:0)
[20:43:59.695] Timer tick, asking Buildbucket for the build status
[20:43:59.927] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:43:59.927] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:14:0) after 1m0s
[20:44:59.954] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:14:0)
[20:44:59.954] Timer tick, asking Buildbucket for the build status
[20:45:00.365] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:45:00.365] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:15:0) after 1m0s
[20:46:00.494] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:15:0)
[20:46:00.494] Timer tick, asking Buildbucket for the build status
[20:46:00.705] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:46:00.705] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:16:0) after 1m0s
[20:47:00.746] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:16:0)
[20:47:00.746] Timer tick, asking Buildbucket for the build status
[20:47:00.992] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:47:00.992] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:17:0) after 1m0s
[20:48:01.090] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:17:0)
[20:48:01.208] Build status: SCHEDULED
[20:48:01.208] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:18:0) after 6m36s
[20:54:37.296] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:18:0)
[20:54:37.296] Timer tick, asking Buildbucket for the build status
[20:54:37.508] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:54:37.508] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:19:0) after 1m0s
[20:55:37.564] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:19:0)
[20:55:37.564] Timer tick, asking Buildbucket for the build status
[20:55:37.841] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:55:37.841] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:20:0) after 1m0s
[20:56:37.857] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:20:0)
[20:56:37.857] Timer tick, asking Buildbucket for the build status
[20:56:38.206] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[20:56:38.206] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:21:0) after 1m0s
[20:57:38.227] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:21:0)
[20:57:38.260] Build status: SCHEDULED
[20:57:38.260] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:22:0) after 3m34s
[21:01:12.372] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:22:0)
[21:01:12.372] Timer tick, asking Buildbucket for the build status
[21:01:12.700] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:01:12.700] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:23:0) after 1m0s
[21:02:12.802] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:23:0)
[21:02:12.843] Build status: SCHEDULED
[21:02:12.844] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:24:0) after 7m31s
[21:09:43.913] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:24:0)
[21:09:44.000] Build status: SCHEDULED
[21:09:44.000] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:25:0) after 2m12s
[21:11:56.109] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:25:0)
[21:11:56.109] Timer tick, asking Buildbucket for the build status
[21:11:57.221] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:11:57.221] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:26:0) after 1m0s
[21:12:57.242] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:26:0)
[21:12:57.242] Timer tick, asking Buildbucket for the build status
[21:12:57.391] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:12:57.391] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:27:0) after 1m0s
[21:13:57.456] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:27:0)
[21:13:57.456] Timer tick, asking Buildbucket for the build status
[21:13:57.741] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:13:57.741] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:28:0) after 1m0s
[21:14:57.797] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:28:0)
[21:14:57.797] Timer tick, asking Buildbucket for the build status
[21:14:58.101] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:14:58.101] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:29:0) after 1m0s
[21:15:58.131] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:29:0)
[21:15:58.242] Build status: SCHEDULED
[21:15:58.242] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:30:0) after 6m52s
[21:22:50.261] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:30:0)
[21:22:50.261] Timer tick, asking Buildbucket for the build status
[21:22:50.352] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:22:50.352] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:31:0) after 1m0s
[21:23:50.397] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:31:0)
[21:23:50.397] Timer tick, asking Buildbucket for the build status
[21:23:50.490] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:23:50.490] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:32:0) after 1m0s
[21:24:50.557] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:32:0)
[21:24:50.557] Timer tick, asking Buildbucket for the build status
[21:24:50.643] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:24:50.643] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:33:0) after 1m0s
[21:25:50.662] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:33:0)
[21:25:50.662] Timer tick, asking Buildbucket for the build status
[21:25:50.806] Build 8852664115517437984: status "SCHEDULED", result "", failure_reason "", cancelation_reason ""
[21:25:50.806] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:34:0) after 1m0s
[21:26:50.920] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:34:0)
[21:26:50.999] Build status: SCHEDULED
[21:26:50.999] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:35:0) after 7m5s
[21:33:46.672] Received PubSub notification, asking Buildbucket for the build status
[21:33:46.794] Build 8852664115517437984: status "STARTED", result "", failure_reason "", cancelation_reason ""
[21:33:56.087] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:35:0)
[21:33:56.117] Build status: STARTED
[21:33:56.117] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:37:0) after 8m54s
[21:42:50.191] Handling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:37:0)
[21:42:50.234] Build status: STARTED
[21:42:50.234] Scheduling timer "check-buildbucket-build-status" (infra/infra-continuous-win10-64:9018094177570482400:38:0) after 6m20s
[21:46:34.715] Received PubSub notification, asking Buildbucket for the build status
[21:46:34.811] Build 8852664115517437984: status "COMPLETED", result "SUCCESS", failure_reason "", cancelation_reason ""
[21:46:34.811] Buildbucket build:
{
"build": {
"bucket": "luci.infra.ci",
"canary_preference": "PROD",
"completed_ts": "1615844794212958",
"created_by": "project:infra",
"created_ts": "1615838623467850",
"id": "8852664115517437984",
"parameters_json": "{\"builder_name\": \"infra-continuous-win10-64\", \"properties\": {\"$recipe_engine/scheduler\": {\"hostname\": \"luci-scheduler-dev.appspot.com\", \"triggers\": [{\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/infra/infra\", \"revision\": \"47503212cf4e2ac3f379c08a979d93025ed448ff\"}, \"id\": \"https://chromium.googlesource.com/infra/infra/+/refs/heads/master@47503212cf4e2ac3f379c08a979d93025ed448ff\", \"title\": \"47503212cf4e2ac3f379c08a979d93025ed448ff\", \"url\": \"https://chromium.googlesource.com/infra/infra/+/47503212cf4e2ac3f379c08a979d93025ed448ff\"}, {\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/infra/infra\", \"revision\": \"895b7bb4e15267d8c7bc342d6f66551819b06577\"}, \"id\": \"https://chromium.googlesource.com/infra/infra/+/refs/heads/master@895b7bb4e15267d8c7bc342d6f66551819b06577\", \"title\": \"895b7bb4e15267d8c7bc342d6f66551819b06577\", \"url\": \"https://chromium.googlesource.com/infra/infra/+/895b7bb4e15267d8c7bc342d6f66551819b06577\"}, {\"gitiles\": {\"ref\": \"refs/heads/master\", \"repo\": \"https://chromium.googlesource.com/infra/infra\", \"revision\": \"08a960b11cbe6c08d428bf215daaf35ac8e09cc9\"}, \"id\": \"https://chromium.googlesource.com/infra/infra/+/refs/heads/master@08a960b11cbe6c08d428bf215daaf35ac8e09cc9\", \"title\": \"08a960b11cbe6c08d428bf215daaf35ac8e09cc9\", \"url\": \"https://chromium.googlesource.com/infra/infra/+/08a960b11cbe6c08d428bf215daaf35ac8e09cc9\"}]}}}",
"project": "infra",
"result": "SUCCESS",
"result_details_json": "{\"properties\": {\"got_revision\": \"08a960b11cbe6c08d428bf215daaf35ac8e09cc9\", \"got_revision_cp\": \"refs/heads/master@{#39359}\"}, \"swarming\": {\"bot_dimensions\": {\"cores\": [\"32\"], \"cpu\": [\"x86\", \"x86-64\", \"x86-64-Broadwell_GCE\"], \"gce\": [\"1\"], \"gcp\": [\"google.com:chromecompute\"], \"gpu\": [\"none\"], \"id\": [\"dev-luci-chromium-ci-win10-0-bozu\"], \"image\": [\"chrome-win10-1703-20111600-a937a23cefb\"], \"integrity\": [\"high\"], \"locale\": [\"en_US.cp1252\"], \"machine_type\": [\"n1-standard-32\"], \"os\": [\"Windows\", \"Windows-10\", \"Windows-10-15063\"], \"pool\": [\"luci.chromium.ci\"], \"python\": [\"2.7.13\"], \"server_version\": [\"5758-b7992b4\"], \"ssd\": [\"0\"], \"windows_client_version\": [\"10\"], \"zone\": [\"us\", \"us-west\", \"us-west1\", \"us-west1-c\"]}}}",
"service_account": "adhoc-testing@luci-token-server-dev.iam.gserviceaccount.com",
"started_ts": "1615844021755336",
"status": "COMPLETED",
"status_changed_ts": "1615844025379638",
"tags": [
"build_address:luci.infra.ci/infra-continuous-win10-64/18868",
"builder:infra-continuous-win10-64",
"buildset:commit/gitiles/chromium.googlesource.com/infra/infra/+/08a960b11cbe6c08d428bf215daaf35ac8e09cc9",
"gitiles_ref:refs/heads/master",
"scheduler_invocation_id:9018094177570482400",
"scheduler_job_id:infra/infra-continuous-win10-64",
"swarming_hostname:chromium-swarm-dev.appspot.com",
"swarming_tag:log_location:logdog://luci-logdog-dev.appspot.com/infra/buildbucket/cr-buildbucket-dev.appspot.com/8852664115517437984/+/annotations",
"swarming_tag:luci_project:infra",
"swarming_tag:os:Windows",
"swarming_tag:recipe_name:infra_continuous",
"swarming_tag:recipe_package:infra/recipe_bundles/chromium.googlesource.com/infra/infra",
"swarming_task_id:52504e418e240110",
"user_agent:luci-scheduler-dev"
],
"updated_ts": "1615844794213275",
"url": "https://luci-milo-dev.appspot.com/b/8852664115517437984",
"utcnow_ts": "1615844794803546"
}
}
[21:46:34.811] Invocation finished in 1h42m52.6849174s with status SUCCEEDED