W1017 17:24:26.181] **************************************************************************
bootstrap.py is deprecated!
test-infra oncall does not support any job still using bootstrap.py.
Please migrate your job to podutils!
https://github.com/kubernetes/test-infra/blob/master/prow/pod-utilities.md
**************************************************************************
I1017 17:24:26.181] Args: --job=chewong-e2e-ccm --service-account=/etc/service-account/service-account.json --upload=gs://kubernetes-jenkins/logs --job=chewong-e2e-ccm --repo=k8s.io/kubernetes=release-1.16 --repo=k8s.io/cloud-provider-azure=master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:84546d4184c381a062c9b0a29a987390dc47f2ce --root=/go/src --service-account=/etc/service-account/service-account.json --timeout=450 --upload=gs://kubernetes-upstream/pr-logs --scenario=kubernetes_e2e -- --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=bazel --provider=skeleton --ginkgo-parallel=30 --test-ccm=True --acsengine-agentpoolcount=1 '--acsengine-admin-username=$AZURE_SSH_USER' '--acsengine-creds=$AZURE_CREDENTIALS' --acsengine-orchestratorRelease=1.16 --acsengine-mastervmsize=Standard_DS2_v2 --acsengine-agentvmsize=Standard_D4s_v3 --acsengine-hyperkube=True --acsengine-ccm=True --acsengine-location=eastus2 '--acsengine-public-key=$AZURE_SSH_PUBLIC_KEY_FILE' --acsengine-template-url=https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json --acsengine-download-url=https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz --timeout=420m
I1017 17:24:26.181] Bootstrap chewong-e2e-ccm...
I1017 17:24:26.185] Builder: e3d91256-f102-11e9-918b-16773c0c7aed
I1017 17:24:26.185] Image: chewong/kubekins-e2e:v20191017-test
I1017 17:24:26.185] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904
I1017 17:24:26.185] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1017 17:24:26.713] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1017 17:24:26.742] process 213 exited with code 0 after 0.0m
I1017 17:24:26.742] Call:  gcloud config get-value account
I1017 17:24:26.993] process 225 exited with code 0 after 0.0m
I1017 17:24:26.994] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1017 17:24:26.994] Root: /go/src
I1017 17:24:26.994] cd to /go/src
I1017 17:24:26.994] Checkout: /go/src/k8s.io/kubernetes release-1.16 to /go/src/k8s.io/kubernetes
I1017 17:24:26.994] Call:  git init k8s.io/kubernetes
I1017 17:24:26.998] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/
I1017 17:24:26.998] process 237 exited with code 0 after 0.0m
I1017 17:24:26.999] Call:  git config --local user.name 'K8S Bootstrap'
I1017 17:24:27.001] process 238 exited with code 0 after 0.0m
I1017 17:24:27.001] Call:  git config --local user.email k8s_bootstrap@localhost
I1017 17:24:27.003] process 239 exited with code 0 after 0.0m
I1017 17:24:27.004] Call:  git fetch --quiet --tags https://github.com/kubernetes/kubernetes release-1.16
I1017 17:25:17.093] process 240 exited with code 0 after 0.8m
I1017 17:25:17.093] Call:  git checkout -B test FETCH_HEAD
W1017 17:25:19.181] Switched to a new branch 'test'
I1017 17:25:19.189] process 252 exited with code 0 after 0.0m
I1017 17:25:19.189] Call:  git show -s --format=format:%ct HEAD
I1017 17:25:19.192] process 253 exited with code 0 after 0.0m
I1017 17:25:19.193] Checkout: /go/src/k8s.io/cloud-provider-azure master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:84546d4184c381a062c9b0a29a987390dc47f2ce to /go/src/k8s.io/cloud-provider-azure
I1017 17:25:19.193] Call:  git init k8s.io/cloud-provider-azure
I1017 17:25:19.196] Initialized empty Git repository in /go/src/k8s.io/cloud-provider-azure/.git/
I1017 17:25:19.197] process 254 exited with code 0 after 0.0m
I1017 17:25:19.197] Call:  git config --local user.name 'K8S Bootstrap'
I1017 17:25:19.199] process 255 exited with code 0 after 0.0m
I1017 17:25:19.200] Call:  git config --local user.email k8s_bootstrap@localhost
I1017 17:25:19.202] process 256 exited with code 0 after 0.0m
I1017 17:25:19.202] Call:  git fetch --quiet --tags https://github.com/kubernetes/cloud-provider-azure master +refs/pull/248/head:refs/pr/248
I1017 17:25:20.633] process 257 exited with code 0 after 0.0m
I1017 17:25:20.633] Call:  git checkout -B test c470e6f36d76e5a565478fcba22118c06bc1548f
W1017 17:25:21.055] Switched to a new branch 'test'
I1017 17:25:21.060] process 269 exited with code 0 after 0.0m
I1017 17:25:21.061] Call:  git show -s --format=format:%ct HEAD
I1017 17:25:21.064] process 270 exited with code 0 after 0.0m
I1017 17:25:21.064] Call:  git merge --no-ff -m 'Merge +refs/pull/248/head:refs/pr/248' 84546d4184c381a062c9b0a29a987390dc47f2ce
I1017 17:25:21.151] Merge made by the 'recursive' strategy.
I1017 17:25:21.153]  hack/log-dump.sh | 171 +++++++++++++++++++++++++++++++++++++++++++++++++++++++
I1017 17:25:21.153]  1 file changed, 171 insertions(+)
I1017 17:25:21.154]  create mode 100755 hack/log-dump.sh
I1017 17:25:21.154] process 271 exited with code 0 after 0.0m
I1017 17:25:21.154] Configure environment...
I1017 17:25:21.154] Call:  git show -s --format=format:%ct HEAD
I1017 17:25:21.158] process 273 exited with code 0 after 0.0m
I1017 17:25:21.158] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1017 17:25:21.760] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1017 17:25:21.865] process 274 exited with code 0 after 0.0m
I1017 17:25:21.865] Call:  gcloud config get-value account
I1017 17:25:22.112] process 286 exited with code 0 after 0.0m
I1017 17:25:22.112] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1017 17:25:22.112] Call:  bash -c '
set -o errexit
set -o nounset
export KUBE_ROOT=.
source hack/lib/version.sh
kube::version::get_version_vars
echo $KUBE_GIT_VERSION
'
I1017 17:25:22.334] process 298 exited with code 0 after 0.0m
I1017 17:25:22.334] Start 1184882818765819904 at v1.16.3-beta.0.11+0d9472c2ffccc1...
I1017 17:25:22.336] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_jP83GC gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904/started.json
I1017 17:25:23.745] process 331 exited with code 0 after 0.0m
I1017 17:25:23.746] Call:  gsutil -q -h Content-Type:text/plain -h 'x-goog-meta-link: gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904' cp /tmp/gsutil_UlYV9q gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/1184882818765819904.txt
I1017 17:25:25.229] process 509 exited with code 0 after 0.0m
I1017 17:25:25.230] Call:  /workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=bazel --provider=skeleton --ginkgo-parallel=30 --test-ccm=True --acsengine-agentpoolcount=1 --acsengine-admin-username=azureuser --acsengine-creds=/etc/azure-cred/credentials --acsengine-orchestratorRelease=1.16 --acsengine-mastervmsize=Standard_DS2_v2 --acsengine-agentvmsize=Standard_D4s_v3 --acsengine-hyperkube=True --acsengine-ccm=True --acsengine-location=eastus2 --acsengine-public-key=/etc/ssh-key-secret/ssh-public --acsengine-template-url=https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json --acsengine-download-url=https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz --timeout=420m
W1017 17:25:25.267] starts with local mode
W1017 17:25:25.267] Environment:
W1017 17:25:25.267] ARTIFACTS=/workspace/_artifacts
W1017 17:25:25.267] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa
W1017 17:25:25.267] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub
W1017 17:25:25.267] AZURE_CREDENTIALS=/etc/azure-cred/credentials
W1017 17:25:25.268] AZURE_SSH_PRIVATE_KEY_FILE=/etc/ssh-key-secret/ssh-private
W1017 17:25:25.268] AZURE_SSH_PUBLIC_KEY_FILE=/etc/ssh-key-secret/ssh-public
W1017 17:25:25.268] AZURE_SSH_USER=azureuser
W1017 17:25:25.268] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer
W1017 17:25:25.269] BAZEL_REMOTE_CACHE_ENABLED=false
W1017 17:25:25.269] BAZEL_VERSION=0.23.2
W1017 17:25:25.269] BOOTSTRAP_MIGRATION=yes
W1017 17:25:25.269] BUILD_ID=1184882818765819904
W1017 17:25:25.269] BUILD_NUMBER=1184882818765819904
W1017 17:25:25.270] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true
W1017 17:25:25.270] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud
W1017 17:25:25.270] CLOUDSDK_CORE_DISABLE_PROMPTS=1
W1017 17:25:25.270] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false
W1017 17:25:25.270] CLOUD_CONFIG=random
W1017 17:25:25.271] DECK_PORT=tcp://10.0.160.83:80
W1017 17:25:25.271] DECK_PORT_80_TCP=tcp://10.0.160.83:80
W1017 17:25:25.271] DECK_PORT_80_TCP_ADDR=10.0.160.83
W1017 17:25:25.271] DECK_PORT_80_TCP_PORT=80
W1017 17:25:25.271] DECK_PORT_80_TCP_PROTO=tcp
W1017 17:25:25.271] DECK_SERVICE_HOST=10.0.160.83
W1017 17:25:25.272] DECK_SERVICE_PORT=80
W1017 17:25:25.272] DOCKER_IN_DOCKER_ENABLED=true
W1017 17:25:25.272] DOCKER_IN_DOCKER_IPV6_ENABLED=false
W1017 17:25:25.272] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904/artifacts
W1017 17:25:25.272] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json
W1017 17:25:25.272] GOPATH=/go
W1017 17:25:25.273] GO_TARBALL=go1.12.10.linux-amd64.tar.gz
W1017 17:25:25.273] HOME=/workspace
W1017 17:25:25.273] HOOK_PORT=tcp://10.0.144.133:8888
W1017 17:25:25.273] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888
W1017 17:25:25.273] HOOK_PORT_8888_TCP_ADDR=10.0.144.133
W1017 17:25:25.273] HOOK_PORT_8888_TCP_PORT=8888
W1017 17:25:25.274] HOOK_PORT_8888_TCP_PROTO=tcp
W1017 17:25:25.274] HOOK_SERVICE_HOST=10.0.144.133
W1017 17:25:25.274] HOOK_SERVICE_PORT=8888
W1017 17:25:25.274] HOSTNAME=e3d91256-f102-11e9-918b-16773c0c7aed
W1017 17:25:25.274] IMAGE=chewong/kubekins-e2e:v20191017-test
W1017 17:25:25.274] INSTANCE_PREFIX=bootstrap-e2e
W1017 17:25:25.274] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/etc/ssh-key-secret/ssh-private
W1017 17:25:25.275] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/etc/ssh-key-secret/ssh-public
W1017 17:25:25.275] JOB_NAME=chewong-e2e-ccm
W1017 17:25:25.275] JOB_SPEC={"type":"presubmit","job":"chewong-e2e-ccm","buildid":"1184882818765819904","prowjobid":"e3d91256-f102-11e9-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"fef819254a061e37c83edf894f43e33479ce1923","base_link":"https://github.com/Azure/kubernetes/commit/fef819254a061e37c83edf894f43e33479ce1923","pulls":[{"number":113,"author":"chewong","sha":"879465972041635fd7bc8269da49153b67e63822","link":"https://github.com/Azure/kubernetes/pull/113","commit_link":"https://github.com/Azure/kubernetes/pull/113/commits/879465972041635fd7bc8269da49153b67e63822","author_link":"https://github.com/chewong"}]}}
W1017 17:25:25.275] JOB_TYPE=presubmit
W1017 17:25:25.276] KUBERNETES_PORT=tcp://10.0.0.1:443
W1017 17:25:25.276] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443
W1017 17:25:25.276] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1
W1017 17:25:25.276] KUBERNETES_PORT_443_TCP_PORT=443
W1017 17:25:25.276] KUBERNETES_PORT_443_TCP_PROTO=tcp
W1017 17:25:25.276] KUBERNETES_SERVICE_HOST=10.0.0.1
W1017 17:25:25.276] KUBERNETES_SERVICE_PORT=443
W1017 17:25:25.277] KUBERNETES_SERVICE_PORT_HTTPS=443
W1017 17:25:25.277] KUBETEST_IN_DOCKER=true
W1017 17:25:25.277] KUBETEST_MANUAL_DUMP=y
W1017 17:25:25.277] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e
W1017 17:25:25.277] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e
W1017 17:25:25.277] KUBE_VERBOSE=0
W1017 17:25:25.278] NODE_NAME=e3d91256-f102-11e9-918b-16773c0c7aed
W1017 17:25:25.278] PATH=/go/bin:/go/bin:/usr/local/go/bin:/google-cloud-sdk/bin:/workspace:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
W1017 17:25:25.278] PROW_JOB_ID=e3d91256-f102-11e9-918b-16773c0c7aed
W1017 17:25:25.278] PULL_BASE_REF=master
W1017 17:25:25.278] PULL_BASE_SHA=fef819254a061e37c83edf894f43e33479ce1923
W1017 17:25:25.278] PULL_NUMBER=113
W1017 17:25:25.279] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822
W1017 17:25:25.279] PULL_REFS=master:fef819254a061e37c83edf894f43e33479ce1923,113:879465972041635fd7bc8269da49153b67e63822
W1017 17:25:25.279] PWD=/workspace
W1017 17:25:25.279] REGISTRY=k8sprowinternal.azurecr.io
W1017 17:25:25.279] REPO_NAME=kubernetes
W1017 17:25:25.279] REPO_OWNER=Azure
W1017 17:25:25.279] SHLVL=2
W1017 17:25:25.280] SOURCE_DATE_EPOCH=1571316399
W1017 17:25:25.280] TERM=xterm
W1017 17:25:25.280] TIDE_PORT=tcp://10.0.180.53:80
W1017 17:25:25.280] TIDE_PORT_80_TCP=tcp://10.0.180.53:80
W1017 17:25:25.280] TIDE_PORT_80_TCP_ADDR=10.0.180.53
W1017 17:25:25.280] TIDE_PORT_80_TCP_PORT=80
W1017 17:25:25.280] TIDE_PORT_80_TCP_PROTO=tcp
W1017 17:25:25.281] TIDE_SERVICE_HOST=10.0.180.53
W1017 17:25:25.281] TIDE_SERVICE_PORT=80
W1017 17:25:25.281] USER=prow
W1017 17:25:25.281] WORKSPACE=/workspace
W1017 17:25:25.281] _=./test-infra/jenkins/bootstrap.py
W1017 17:25:25.282] Run: ('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=bazel', '--up', '--down', '--test', '--deployment=acsengine', '--provider=skeleton', '--cluster=bootstrap-e2e', '--gcp-network=bootstrap-e2e', '--ginkgo-parallel=30', '--test-ccm=True', '--acsengine-agentpoolcount=1', '--acsengine-admin-username=azureuser', '--acsengine-creds=/etc/azure-cred/credentials', '--acsengine-orchestratorRelease=1.16', '--acsengine-mastervmsize=Standard_DS2_v2', '--acsengine-agentvmsize=Standard_D4s_v3', '--acsengine-hyperkube=True', '--acsengine-ccm=True', '--acsengine-location=eastus2', '--acsengine-public-key=/etc/ssh-key-secret/ssh-public', '--acsengine-template-url=https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json', '--acsengine-download-url=https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz', '--timeout=420m')
W1017 17:25:25.282] 2019/10/17 17:25:25 main.go:332: Limiting testing to 7h0m0s
W1017 17:25:25.282] 2019/10/17 17:25:25 azure.go:232: Reading credentials file /etc/azure-cred/credentials
W1017 17:25:25.282] 2019/10/17 17:25:25 process.go:153: Running: make -C /go/src/k8s.io/kubernetes bazel-release
W1017 17:25:25.308] Extracting Bazel installation...
I1017 17:25:25.408] make: Entering directory '/go/src/k8s.io/kubernetes'
W1017 17:25:34.124] Starting local Bazel server and connecting to it...
W1017 17:25:35.905] Loading: 
W1017 17:25:35.908] Loading: 0 packages loaded
W1017 17:25:36.910] Loading: 0 packages loaded
W1017 17:25:38.472] Loading: 0 packages loaded
W1017 17:25:39.912] Loading: 0 packages loaded
W1017 17:25:41.657] Loading: 0 packages loaded
W1017 17:25:42.912] Loading: 0 packages loaded
W1017 17:25:42.912]     currently loading: build/release-tars
W1017 17:25:44.919] Loading: 0 packages loaded
W1017 17:25:44.920]     currently loading: build/release-tars
W1017 17:25:45.307] Analyzing: target //build/release-tars:release-tars (1 packages loaded, 0 targets configured)
W1017 17:25:46.739] Analyzing: target //build/release-tars:release-tars (123 packages loaded, 751 targets configured)
W1017 17:25:48.388] Analyzing: target //build/release-tars:release-tars (858 packages loaded, 3325 targets configured)
W1017 17:25:50.292] Analyzing: target //build/release-tars:release-tars (1466 packages loaded, 8637 targets configured)
W1017 17:25:52.475] Analyzing: target //build/release-tars:release-tars (2162 packages loaded, 16348 targets configured)
W1017 17:25:56.086] Analyzing: target //build/release-tars:release-tars (3032 packages loaded, 27381 targets configured)
W1017 17:25:59.223] Analyzing: target //build/release-tars:release-tars (3060 packages loaded, 27862 targets configured)
W1017 17:26:02.932] Analyzing: target //build/release-tars:release-tars (3071 packages loaded, 34088 targets configured)
W1017 17:26:09.775] Analyzing: target //build/release-tars:release-tars (3077 packages loaded, 35846 targets configured)
W1017 17:26:24.642] INFO: Analysed target //build/release-tars:release-tars (3077 packages loaded, 42527 targets configured).
W1017 17:26:24.644] Building: checking cached actions
W1017 17:26:24.645] INFO: Found 1 target...
W1017 17:26:24.826] [0 / 16] [-----] BazelWorkspaceStatusAction stable-status.txt
W1017 17:26:32.215] [153 / 5,304] GoCompile vendor/github.com/gogo/protobuf/proto/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/gogo/protobuf/proto.a; 2s linux-sandbox ... (8 actions, 6 running)
W1017 17:26:40.905] [279 / 5,304] GoCompile vendor/github.com/golang/protobuf/jsonpb/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/golang/protobuf/jsonpb.a; 2s linux-sandbox ... (8 actions running)
W1017 17:26:50.677] [427 / 5,304] GoCompile vendor/github.com/emicklei/go-restful/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/emicklei/go-restful.a [for host]; 1s linux-sandbox ... (8 actions running)
W1017 17:27:03.404] [541 / 5,304] GoCompile vendor/github.com/globalsign/mgo/internal/json/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/globalsign/mgo/internal/json.a; 3s linux-sandbox ... (8 actions, 7 running)
W1017 17:27:19.257] [708 / 5,304] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 8s linux-sandbox ... (5 actions running)
W1017 17:27:34.798] [1,119 / 5,304] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 24s linux-sandbox ... (7 actions running)
W1017 17:27:52.713] [1,342 / 5,304] GoCompile vendor/github.com/google/go-cmp/cmp/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/google/go-cmp/cmp.a; 0s linux-sandbox ... (8 actions, 7 running)
W1017 17:28:14.299] [1,491 / 5,304] GoCompile vendor/golang.org/x/net/idna/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/golang.org/x/net/idna.a; 4s linux-sandbox ... (6 actions, 4 running)
W1017 17:28:38.186] [1,694 / 5,304] GoAsm vendor/gonum.org/v1/gonum/internal/asm/c128/linux_amd64_pure_stripped/go_default_library%/dotcunitary_amd64.o; 1s linux-sandbox ... (8 actions, 7 running)
W1017 17:29:06.621] [1,923 / 5,304] GoCompile vendor/github.com/vmware/govmomi/vim25/types/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/types.a; 15s linux-sandbox ... (8 actions, 7 running)
W1017 17:29:39.072] [2,194 / 5,304] GoCompile vendor/github.com/coreos/etcd/pkg/transport/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/coreos/etcd/pkg/transport.a; 1s linux-sandbox ... (8 actions, 6 running)
W1017 17:29:39.075] [2,195 / 5,304] GoCompile vendor/github.com/coreos/etcd/pkg/transport/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/coreos/etcd/pkg/transport.a; 1s linux-sandbox ... (7 actions, 6 running)
W1017 17:30:16.810] [2,542 / 5,304] GoCompile vendor/github.com/storageos/go-api/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/storageos/go-api.a; 2s linux-sandbox ... (8 actions, 7 running)
W1017 17:30:58.968] [2,724 / 5,304] GoPath staging/src/k8s.io/sample-apiserver/pkg/generated/openapi/zz_generated.openapi~gopath/src/k8s.io/kubernetes/vendor/github.com/go-openapi/spec/bindata.go; 9s linux-sandbox ... (8 actions, 7 running)
W1017 17:31:48.588] [2,839 / 5,304] GoCompile staging/src/k8s.io/api/admissionregistration/v1beta1/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/api/admissionregistration/v1beta1.a; 3s linux-sandbox ... (7 actions, 6 running)
W1017 17:32:45.077] [3,130 / 5,304] GoCompile cmd/kubeadm/app/apis/kubeadm/v1beta1/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/cmd/kubeadm/app/apis/kubeadm/v1beta1.a; 1s linux-sandbox ... (8 actions, 7 running)
W1017 17:33:49.718] [3,622 / 5,304] GoCompile staging/src/k8s.io/kubectl/pkg/cmd/apply/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/kubectl/pkg/cmd/apply.a; 2s linux-sandbox ... (8 actions, 7 running)
W1017 17:35:03.985] [3,911 / 5,304] GoCompile test/e2e/framework/metrics/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/test/e2e/framework/metrics.a; 5s linux-sandbox ... (8 actions, 7 running)
W1017 17:36:29.417] [4,521 / 5,304] GoCompile staging/src/k8s.io/apiextensions-apiserver/pkg/generated/openapi/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/apiextensions-apiserver/pkg/generated/openapi.a; 11s linux-sandbox ... (8 actions, 7 running)
W1017 17:38:07.503] [4,987 / 5,304] GoCompile pkg/controller/volume/scheduling/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/pkg/controller/volume/scheduling.a; 5s linux-sandbox ... (8 actions, 7 running)
W1017 17:40:00.570] [5,197 / 5,304] GoLink cmd/hyperkube/hyperkube; 26s linux-sandbox ... (8 actions running)
W1017 17:42:12.381] Slow read: a 141554116-byte read from /workspace/.cache/bazel/_bazel_prow/48d5366022b4e3197674c8d6e2bee219/execroot/io_k8s_kubernetes/bazel-out/k8-fastbuild/bin/cmd/kube-controller-manager/linux_amd64_pure_stripped/kube-controller-manager took 23193 ms.
W1017 17:42:12.402] [5,266 / 5,304] GoLink cmd/hyperkube/hyperkube; 158s linux-sandbox ... (8 actions, 6 running)
W1017 17:42:37.043] Slow read: a 53368832-byte read from /workspace/.cache/bazel/_bazel_prow/48d5366022b4e3197674c8d6e2bee219/execroot/io_k8s_kubernetes/bazel-out/k8-fastbuild/bin/build/release-tars/_client-bin.tar took 20994 ms.
W1017 17:43:03.246] Slow read: a 141557254-byte read from /workspace/.cache/bazel/_bazel_prow/48d5366022b4e3197674c8d6e2bee219/execroot/io_k8s_kubernetes/bazel-out/k8-fastbuild/bin/build/debs/kube-controller-manager-amd64.deb took 21862 ms.
W1017 17:43:32.088] Slow read: a 108102531-byte read from /workspace/.cache/bazel/_bazel_prow/48d5366022b4e3197674c8d6e2bee219/execroot/io_k8s_kubernetes/bazel-out/k8-fastbuild/bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz took 26129 ms.
W1017 17:44:43.127] [5,302 / 5,304] PackageTar build/release-tars/_server-bin.tar; 18s linux-sandbox
W1017 17:45:16.509] Target //build/release-tars:release-tars up-to-date:
W1017 17:45:16.510]   bazel-bin/build/release-tars/kubernetes-client-linux-amd64.tar.gz
W1017 17:45:16.511]   bazel-bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz
W1017 17:45:16.511]   bazel-bin/build/release-tars/kubernetes-server-linux-amd64.tar.gz
W1017 17:45:16.511]   bazel-bin/build/release-tars/kubernetes-manifests.tar.gz
W1017 17:45:16.511]   bazel-bin/build/release-tars/kubernetes-test-portable.tar.gz
W1017 17:45:16.512]   bazel-bin/build/release-tars/kubernetes-test-linux-amd64.tar.gz
W1017 17:45:16.512]   bazel-bin/build/release-tars/kubernetes-test.tar.gz
W1017 17:45:16.512]   bazel-bin/build/release-tars/kubernetes.tar.gz
W1017 17:45:16.512]   bazel-bin/build/release-tars/kubernetes-src.tar.gz
W1017 17:45:16.549] INFO: Elapsed time: 1191.186s, Critical Path: 419.38s
W1017 17:45:16.550] INFO: 5211 processes: 5211 linux-sandbox.
W1017 17:45:16.554] INFO: Build completed successfully, 5304 total actions
W1017 17:45:16.556] INFO: Build completed successfully, 5304 total actions
I1017 17:45:16.816] make: Leaving directory '/go/src/k8s.io/kubernetes'
W1017 17:45:16.916] 2019/10/17 17:45:16 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes bazel-release' finished in 19m51.533455201s
W1017 17:45:16.916] 2019/10/17 17:45:16 util.go:277: Flushing memory.
W1017 17:45:44.313] 2019/10/17 17:45:44 azure.go:906: Deleting resource group: kubetest-1b114a50-f103-11e9-baf9-0242825fb6e1.
W1017 17:45:44.852] 2019/10/17 17:45:44 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1017 17:45:44.853] 2019/10/17 17:45:44 azure.go:673: Attempting Docker login with azure cred.
W1017 17:45:46.319] 2019/10/17 17:45:46 azure.go:682: Docker login success.
W1017 17:45:46.320] 2019/10/17 17:45:46 azure.go:697: Building ccm.
W1017 17:45:46.320] 2019/10/17 17:45:46 azure.go:699: projectPath /go/src/k8s.io/cloud-provider-azure
W1017 17:45:46.320] 2019/10/17 17:45:46 process.go:153: Running: docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184882818765819904-f1fcf501 .
I1017 17:45:48.596] Sending build context to Docker daemon  67.18MB

I1017 17:45:48.631] Step 1/7 : FROM golang:1.12.9-stretch AS build
I1017 17:45:49.726] 1.12.9-stretch: Pulling from library/golang
I1017 17:45:50.049] 092586df9206: Pulling fs layer
I1017 17:45:50.049] ef599477fae0: Pulling fs layer
I1017 17:45:50.049] 4530c6472b5d: Pulling fs layer
I1017 17:45:50.049] d34d61487075: Pulling fs layer
I1017 17:45:50.049] 89c6ec31b9e9: Pulling fs layer
I1017 17:45:50.050] e37857ebcafa: Pulling fs layer
I1017 17:45:50.050] b0e29f6c7f0a: Pulling fs layer
I1017 17:45:50.050] 89c6ec31b9e9: Waiting
I1017 17:45:50.050] e37857ebcafa: Waiting
I1017 17:45:50.050] b0e29f6c7f0a: Waiting
I1017 17:45:50.051] d34d61487075: Waiting
I1017 17:45:50.493] 4530c6472b5d: Download complete
I1017 17:45:50.526] ef599477fae0: Verifying Checksum
I1017 17:45:50.526] ef599477fae0: Download complete
I1017 17:45:50.896] 092586df9206: Verifying Checksum
I1017 17:45:50.896] 092586df9206: Download complete
I1017 17:45:51.287] d34d61487075: Verifying Checksum
I1017 17:45:51.287] d34d61487075: Download complete
I1017 17:45:51.523] 89c6ec31b9e9: Verifying Checksum
I1017 17:45:51.523] 89c6ec31b9e9: Download complete
I1017 17:45:51.646] b0e29f6c7f0a: Download complete
I1017 17:45:52.633] e37857ebcafa: Verifying Checksum
I1017 17:45:52.634] e37857ebcafa: Download complete
I1017 17:45:54.127] 092586df9206: Pull complete
I1017 17:45:54.926] ef599477fae0: Pull complete
I1017 17:45:55.293] 4530c6472b5d: Pull complete
I1017 17:45:58.967] d34d61487075: Pull complete
I1017 17:46:02.483] 89c6ec31b9e9: Pull complete
I1017 17:46:10.008] e37857ebcafa: Pull complete
I1017 17:46:10.159] b0e29f6c7f0a: Pull complete
I1017 17:46:10.183] Digest: sha256:76b52857546f070cc3ac499accb27b8c411b10ff6d45c0b1da2a8aab7b61fe29
I1017 17:46:10.204] Status: Downloaded newer image for golang:1.12.9-stretch
I1017 17:46:10.205]  ---> 2c4a601e5da9
I1017 17:46:10.205] Step 2/7 : WORKDIR /go/src/k8s.io/cloud-provider-azure
I1017 17:46:22.191]  ---> Running in f140d6f35a97
I1017 17:46:23.375] Removing intermediate container f140d6f35a97
I1017 17:46:23.376]  ---> 7d54bcb5e981
I1017 17:46:23.376] Step 3/7 : COPY . .
I1017 17:46:29.399]  ---> 5a52a5cdfdec
I1017 17:46:29.400] Step 4/7 : RUN make
I1017 17:46:29.636]  ---> Running in 422a4267b04f
I1017 17:46:30.532] hack/pkg-config.sh > .pkg_config
I1017 17:46:30.559] go build -o bin/azure-cloud-controller-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-11-gfe3b13bf4 -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=fe3b13bf4e70c53da8e014490b97daeec1950fe1 -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-17T17:46:30Z' ./cmd/cloud-controller-manager
I1017 17:47:13.279] go build -o bin/azure-cloud-node-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-11-gfe3b13bf4 -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=fe3b13bf4e70c53da8e014490b97daeec1950fe1 -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-17T17:46:30Z' ./cmd/cloud-node-manager
I1017 17:47:37.392] Removing intermediate container 422a4267b04f
I1017 17:47:37.392]  ---> e369b9088bf7
I1017 17:47:37.392] Step 5/7 : FROM k8s.gcr.io/debian-base:v1.0.0
I1017 17:47:37.773] v1.0.0: Pulling from debian-base
I1017 17:47:37.935] 39fafc05754f: Pulling fs layer
I1017 17:47:38.330] 39fafc05754f: Verifying Checksum
I1017 17:47:38.331] 39fafc05754f: Download complete
I1017 17:47:40.989] 39fafc05754f: Pull complete
I1017 17:47:41.018] Digest: sha256:3801f944c765dc1b54900826ca67b1380bb8c73b9caf4a2a27ce613b3ba3e742
I1017 17:47:41.037] Status: Downloaded newer image for k8s.gcr.io/debian-base:v1.0.0
I1017 17:47:41.037]  ---> 204e96332c91
I1017 17:47:41.037] Step 6/7 : COPY --from=build /go/src/k8s.io/cloud-provider-azure/bin/azure-cloud-controller-manager /usr/local/bin
I1017 17:47:44.052]  ---> 47542663a58e
I1017 17:47:44.052] Step 7/7 : RUN ln -s /usr/local/bin/azure-cloud-controller-manager /usr/local/bin/cloud-controller-manager
I1017 17:47:44.210]  ---> Running in 8278c4812dd1
I1017 17:47:46.054] Removing intermediate container 8278c4812dd1
I1017 17:47:46.055]  ---> 9c929733876d
I1017 17:47:46.174] Successfully built 9c929733876d
I1017 17:47:46.411] Successfully tagged k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184882818765819904-f1fcf501
W1017 17:47:46.512] 2019/10/17 17:47:46 process.go:155: Step 'docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184882818765819904-f1fcf501 .' finished in 2m0.096473265s
W1017 17:47:46.512] 2019/10/17 17:47:46 process.go:153: Running: docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184882818765819904-f1fcf501
W1017 17:47:50.788] 2019/10/17 17:47:50 process.go:155: Step 'docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184882818765819904-f1fcf501' finished in 4.371856288s
W1017 17:47:50.788] 2019/10/17 17:47:50 azure.go:686: Docker logout.
W1017 17:47:50.856] 2019/10/17 17:47:50 azure.go:716: Custom cloud controller manager URL: k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184882818765819904-f1fcf501 .
W1017 17:47:50.857] 2019/10/17 17:47:50 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1017 17:47:50.857] 2019/10/17 17:47:50 azure.go:673: Attempting Docker login with azure cred.
W1017 17:47:51.702] 2019/10/17 17:47:51 azure.go:682: Docker login success.
W1017 17:47:51.703] 2019/10/17 17:47:51 azure.go:726: Building hyperkube.
W1017 17:47:51.703] 2019/10/17 17:47:51 process.go:153: Running: make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube
W1017 17:48:17.199] found packages rand (cgo1.go) and rand2 (cgo2.go) in /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/bazel-kubernetes/external/go_sdk/doc/progs
W1017 17:50:58.787] 2019/10/17 17:50:58 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube' finished in 3m7.085093125s
W1017 17:50:58.788] 2019/10/17 17:50:58 azure.go:733: Pushing hyperkube.
W1017 17:50:58.788] 2019/10/17 17:50:58 process.go:153: Running: make -C /go/src/k8s.io/kubernetes/cluster/images/hyperkube push HYPERKUBE_BIN=/go/src/k8s.io/kubernetes/_output/bin/hyperkube
I1017 17:50:58.888] make: Entering directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
I1017 17:50:58.889] cp -r ./* /tmp/hyperkubeAQ95AR
I1017 17:50:58.889] cp /go/src/k8s.io/kubernetes/_output/bin/hyperkube /tmp/hyperkubeAQ95AR
I1017 17:50:58.963] chmod a+rx /tmp/hyperkubeAQ95AR/hyperkube
I1017 17:50:58.965] cd /tmp/hyperkubeAQ95AR && sed -i.back "s|BASEIMAGE|k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1|g" Dockerfile
I1017 17:50:58.967] docker build --pull -t k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184882818765819904-3d17996c /tmp/hyperkubeAQ95AR
I1017 17:51:00.280] Sending build context to Docker daemon  212.1MB

I1017 17:51:00.307] Step 1/2 : FROM k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1017 17:51:00.645] 0.12.1: Pulling from debian-hyperkube-base-amd64
I1017 17:51:00.645] 346aee5ea5bc: Pulling fs layer
I1017 17:51:00.645] 9c47fde751af: Pulling fs layer
I1017 17:51:00.646] be2693a52daf: Pulling fs layer
I1017 17:51:00.646] 6b69eb11d043: Pulling fs layer
I1017 17:51:00.646] 0abeb1500767: Pulling fs layer
I1017 17:51:00.646] 4062d80041b7: Pulling fs layer
I1017 17:51:00.646] 23b6daf06fc2: Pulling fs layer
I1017 17:51:00.646] 6b69eb11d043: Waiting
I1017 17:51:00.646] 0abeb1500767: Waiting
I1017 17:51:00.647] 4062d80041b7: Waiting
I1017 17:51:00.647] 23b6daf06fc2: Waiting
I1017 17:51:00.783] 9c47fde751af: Verifying Checksum
I1017 17:51:00.784] 9c47fde751af: Download complete
I1017 17:51:00.810] be2693a52daf: Verifying Checksum
I1017 17:51:00.810] be2693a52daf: Download complete
I1017 17:51:00.919] 6b69eb11d043: Verifying Checksum
I1017 17:51:00.919] 6b69eb11d043: Download complete
I1017 17:51:00.943] 0abeb1500767: Verifying Checksum
I1017 17:51:00.943] 0abeb1500767: Download complete
I1017 17:51:01.033] 346aee5ea5bc: Verifying Checksum
I1017 17:51:01.034] 346aee5ea5bc: Download complete
I1017 17:51:01.579] 23b6daf06fc2: Verifying Checksum
I1017 17:51:01.580] 23b6daf06fc2: Download complete
I1017 17:51:02.348] 4062d80041b7: Verifying Checksum
I1017 17:51:02.349] 4062d80041b7: Download complete
I1017 17:51:07.436] 346aee5ea5bc: Pull complete
I1017 17:51:07.580] 9c47fde751af: Pull complete
I1017 17:51:07.786] be2693a52daf: Pull complete
I1017 17:51:07.929] 6b69eb11d043: Pull complete
I1017 17:51:08.070] 0abeb1500767: Pull complete
I1017 17:51:15.669] 4062d80041b7: Pull complete
I1017 17:51:16.701] 23b6daf06fc2: Pull complete
I1017 17:51:16.724] Digest: sha256:5d4ea2fb5fbe9a9a9da74f67cf2faefc881968bc39f2ac5d62d9167e575812a1
I1017 17:51:16.742] Status: Downloaded newer image for k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1017 17:51:16.743]  ---> a46476511725
I1017 17:51:16.743] Step 2/2 : COPY hyperkube /hyperkube
I1017 17:51:40.394]  ---> 971f287a24bc
I1017 17:51:40.420] Successfully built 971f287a24bc
I1017 17:51:40.500] Successfully tagged k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184882818765819904-3d17996c
I1017 17:51:40.503] rm -rf "/tmp/hyperkubeAQ95AR"
I1017 17:51:40.531] docker push k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184882818765819904-3d17996c
I1017 17:51:40.597] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube-amd64]
I1017 17:51:40.609] 35ff376e88ed: Preparing
I1017 17:51:40.609] 39b3ac6d96e9: Preparing
I1017 17:51:40.609] 7bbae4dddb88: Preparing
I1017 17:51:40.609] a00defcfe869: Preparing
I1017 17:51:40.609] 2ab0ae805c74: Preparing
I1017 17:51:40.610] 43a8fe7d2382: Preparing
I1017 17:51:40.610] 3f6a6f542637: Preparing
I1017 17:51:40.610] 5ba3be777c2d: Preparing
I1017 17:51:40.610] 43a8fe7d2382: Waiting
I1017 17:51:40.610] 3f6a6f542637: Waiting
I1017 17:51:40.610] 5ba3be777c2d: Waiting
I1017 17:51:40.762] 39b3ac6d96e9: Layer already exists
I1017 17:51:40.786] a00defcfe869: Layer already exists
I1017 17:51:40.819] 7bbae4dddb88: Layer already exists
I1017 17:51:40.829] 2ab0ae805c74: Layer already exists
I1017 17:51:40.866] 43a8fe7d2382: Layer already exists
I1017 17:51:40.905] 5ba3be777c2d: Layer already exists
I1017 17:51:40.926] 3f6a6f542637: Layer already exists
I1017 17:51:50.882] 35ff376e88ed: Pushed
I1017 17:51:51.569] azure-e2e-1184882818765819904-3d17996c: digest: sha256:f9fdf95dd64713eaba169866b7c3f35046d855da8bd4ffa9da74473f9b7a0cff size: 1998
I1017 17:51:51.591] docker rmi k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184882818765819904-3d17996c 2>/dev/null || true
I1017 17:51:51.636] docker tag k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184882818765819904-3d17996c k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184882818765819904-3d17996c
I1017 17:51:51.700] docker push k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184882818765819904-3d17996c
I1017 17:51:51.760] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube]
I1017 17:51:51.771] 35ff376e88ed: Preparing
I1017 17:51:51.771] 39b3ac6d96e9: Preparing
I1017 17:51:51.771] 7bbae4dddb88: Preparing
I1017 17:51:51.771] a00defcfe869: Preparing
I1017 17:51:51.771] 2ab0ae805c74: Preparing
I1017 17:51:51.772] 43a8fe7d2382: Preparing
I1017 17:51:51.772] 3f6a6f542637: Preparing
I1017 17:51:51.772] 5ba3be777c2d: Preparing
I1017 17:51:51.772] 43a8fe7d2382: Waiting
I1017 17:51:51.772] 3f6a6f542637: Waiting
I1017 17:51:51.862] a00defcfe869: Layer already exists
I1017 17:51:51.885] 39b3ac6d96e9: Layer already exists
I1017 17:51:51.923] 2ab0ae805c74: Layer already exists
I1017 17:51:51.945] 7bbae4dddb88: Layer already exists
I1017 17:51:51.961] 35ff376e88ed: Mounted from hyperkube-amd64
I1017 17:51:51.966] 43a8fe7d2382: Layer already exists
I1017 17:51:51.977] 3f6a6f542637: Layer already exists
I1017 17:51:52.034] 5ba3be777c2d: Layer already exists
I1017 17:51:52.569] azure-e2e-1184882818765819904-3d17996c: digest: sha256:f9fdf95dd64713eaba169866b7c3f35046d855da8bd4ffa9da74473f9b7a0cff size: 1998
I1017 17:51:52.584] make: Leaving directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
W1017 17:51:52.685] 2019/10/17 17:51:52 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes/cluster/images/hyperkube push HYPERKUBE_BIN=/go/src/k8s.io/kubernetes/_output/bin/hyperkube' finished in 53.796756289s
W1017 17:51:52.685] 2019/10/17 17:51:52 azure.go:686: Docker logout.
W1017 17:51:52.685] 2019/10/17 17:51:52 azure.go:744: Custom hyperkube URL: k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184882818765819904-3d17996c .
W1017 17:51:52.686] 2019/10/17 17:51:52 azure.go:787: downloading /workspace/aks568643489/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json.
W1017 17:51:52.686] 2019/10/17 17:51:52 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json
W1017 17:51:52.851] 2019/10/17 17:51:52 azure.go:529: downloading /workspace/aks-engine.tar.gz from https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz.
W1017 17:51:52.851] 2019/10/17 17:51:52 util.go:42: curl https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz
W1017 17:51:53.989] 2019/10/17 17:51:53 azure.go:556: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes .
W1017 17:51:53.989] 2019/10/17 17:51:53 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1
W1017 17:51:54.139] 2019/10/17 17:51:54 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 149.948742ms
W1017 17:51:54.139] 2019/10/17 17:51:54 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks568643489/kubernetes.json --output-directory /workspace/aks568643489
I1017 17:51:54.344] INFO[0000] Generating assets into /workspace/aks568643489... 
W1017 17:52:06.790] 2019/10/17 17:52:06 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks568643489/kubernetes.json --output-directory /workspace/aks568643489' finished in 12.650914076s
W1017 17:52:06.793] 2019/10/17 17:52:06 azure.go:627: Setting kubeconfig env variable: kubeconfig path: /workspace/aks568643489/kubeconfig/kubeconfig.eastus2.json.
W1017 17:52:06.794] 2019/10/17 17:52:06 azure.go:629: Creating resource group: kubetest-1b114a50-f103-11e9-baf9-0242825fb6e1.
W1017 17:52:06.794] 2019/10/17 17:52:06 azure.go:631: Creating Azure resource group: kubetest-1b114a50-f103-11e9-baf9-0242825fb6e1 for cluster deployment.
W1017 17:52:08.297] 2019/10/17 17:52:08 azure.go:636: Validating deployment ARM templates.
W1017 17:52:10.455] 2019/10/17 17:52:10 azure.go:642: Deploying cluster kubetest-1b114a50-f103-11e9-baf9-0242825fb6e1 in resource group kubetest-1b114a50-f103-11e9-baf9-0242825fb6e1.
W1017 18:05:21.156] 2019/10/17 18:05:21 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version
W1017 18:05:21.885] 2019/10/17 18:05:21 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 729.508551ms
W1017 18:05:21.886] 2019/10/17 18:05:21 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false get nodes -oyaml
W1017 18:05:23.235] 2019/10/17 18:05:23 process.go:155: Step './cluster/kubectl.sh --match-server-version=false get nodes -oyaml' finished in 1.349975228s
W1017 18:05:23.236] 2019/10/17 18:05:23 azure.go:963: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos.
W1017 18:05:23.236] 2019/10/17 18:05:23 azure.go:963: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos.
W1017 18:05:23.237] 2019/10/17 18:05:23 process.go:153: Running: kubectl get nodes --no-headers
W1017 18:05:23.833] 2019/10/17 18:05:23 process.go:155: Step 'kubectl get nodes --no-headers' finished in 596.580785ms
W1017 18:05:23.834] 2019/10/17 18:05:23 e2e.go:462: Cluster nodes:
W1017 18:05:23.834] k8s-agentpool1-37924729-0   Ready   agent    81s   v1.16.3-beta.0.11+0d9472c2ffccc1
W1017 18:05:23.834] k8s-master-37924729-0       Ready   master   82s   v1.16.3-beta.0.11+0d9472c2ffccc1
W1017 18:05:23.834] 2019/10/17 18:05:23 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version
W1017 18:05:24.255] 2019/10/17 18:05:24 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 421.583682ms
W1017 18:05:24.255] 2019/10/17 18:05:24 azure.go:916: Attempting to dump control-plane and node component logs to /workspace/_artifacts
W1017 18:05:24.256] 2019/10/17 18:05:24 process.go:153: Running: ./hack/log-dump.sh /workspace/_artifacts
W1017 18:05:24.256] 2019/10/17 18:05:24 process.go:155: Step './hack/log-dump.sh /workspace/_artifacts' finished in 1.074209ms
W1017 18:05:24.256] 2019/10/17 18:05:24 azure.go:906: Deleting resource group: kubetest-1b114a50-f103-11e9-baf9-0242825fb6e1.
W1017 18:16:40.342] 2019/10/17 18:16:40 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml.
W1017 18:16:40.343] 2019/10/17 18:16:40 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
W1017 18:16:40.493] 2019/10/17 18:16:40 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 151.037609ms
W1017 18:16:40.494] 2019/10/17 18:16:40 main.go:319: Something went wrong: encountered 1 errors: [error starting ./hack/log-dump.sh /workspace/_artifacts: fork/exec ./hack/log-dump.sh: exec format error]
W1017 18:16:40.496] Traceback (most recent call last):
W1017 18:16:40.496]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module>
W1017 18:16:40.497]     main(parse_args())
W1017 18:16:40.497]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main
W1017 18:16:40.497]     mode.start(runner_args)
W1017 18:16:40.497]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start
W1017 18:16:40.497]     check_env(env, self.command, *args)
W1017 18:16:40.497]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env
W1017 18:16:40.497]     subprocess.check_call(cmd, env=env)
W1017 18:16:40.498]   File "/usr/lib/python2.7/subprocess.py", line 186, in check_call
W1017 18:16:40.498]     raise CalledProcessError(retcode, cmd)
W1017 18:16:40.498] subprocess.CalledProcessError: Command '('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=bazel', '--up', '--down', '--test', '--deployment=acsengine', '--provider=skeleton', '--cluster=bootstrap-e2e', '--gcp-network=bootstrap-e2e', '--ginkgo-parallel=30', '--test-ccm=True', '--acsengine-agentpoolcount=1', '--acsengine-admin-username=azureuser', '--acsengine-creds=/etc/azure-cred/credentials', '--acsengine-orchestratorRelease=1.16', '--acsengine-mastervmsize=Standard_DS2_v2', '--acsengine-agentvmsize=Standard_D4s_v3', '--acsengine-hyperkube=True', '--acsengine-ccm=True', '--acsengine-location=eastus2', '--acsengine-public-key=/etc/ssh-key-secret/ssh-public', '--acsengine-template-url=https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json', '--acsengine-download-url=https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz', '--timeout=420m')' returned non-zero exit status 1
E1017 18:16:40.504] Command failed
I1017 18:16:40.504] process 687 exited with code 1 after 51.3m
E1017 18:16:40.504] FAIL: chewong-e2e-ccm
I1017 18:16:40.504] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1017 18:16:41.357] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1017 18:16:41.390] process 2720 exited with code 0 after 0.0m
I1017 18:16:41.390] Call:  gcloud config get-value account
I1017 18:16:41.650] process 2732 exited with code 0 after 0.0m
I1017 18:16:41.651] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1017 18:16:41.651] Upload result and artifacts...
I1017 18:16:41.651] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904
I1017 18:16:41.651] Call:  gsutil ls gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904/artifacts
W1017 18:16:42.843] CommandException: One or more URLs matched no objects.
E1017 18:16:42.920] Command failed
I1017 18:16:42.920] process 2744 exited with code 1 after 0.0m
W1017 18:16:42.920] Remote dir gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904/artifacts not exist yet
I1017 18:16:42.920] Call:  gsutil -m -q -o GSUtil:use_magicfile=True cp -r -c -z log,txt,xml /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904/artifacts
I1017 18:16:44.613] process 2886 exited with code 0 after 0.0m
I1017 18:16:44.613] Call:  git rev-parse HEAD
I1017 18:16:44.616] process 3413 exited with code 0 after 0.0m
I1017 18:16:44.617] Call:  git rev-parse HEAD
I1017 18:16:44.620] process 3414 exited with code 0 after 0.0m
I1017 18:16:44.620] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1017 18:16:45.587] process 3415 exited with code 0 after 0.0m
I1017 18:16:45.588] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json#1571333349469266'
I1017 18:16:46.825] process 3557 exited with code 0 after 0.0m
I1017 18:16:46.826] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571333349469266 cp /tmp/gsutil_jvNQFF gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1017 18:16:48.173] process 3701 exited with code 0 after 0.0m
I1017 18:16:48.173] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1017 18:16:49.139] process 3879 exited with code 0 after 0.0m
I1017 18:16:49.140] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json#1571333356566283'
I1017 18:16:50.394] process 4021 exited with code 0 after 0.0m
I1017 18:16:50.394] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571333356566283 cp /tmp/gsutil_DHzHCz gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1017 18:16:51.793] process 4165 exited with code 0 after 0.0m
I1017 18:16:51.794] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_Hix3Pc gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184882818765819904/finished.json
I1017 18:16:53.189] process 4343 exited with code 0 after 0.0m
I1017 18:16:53.190] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_WikbUj gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/latest-build.txt
I1017 18:16:54.686] process 4521 exited with code 0 after 0.0m
I1017 18:16:54.687] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_YQ1DYc gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/latest-build.txt
I1017 18:16:56.080] process 4699 exited with code 0 after 0.0m