W1016 23:53:26.402] **************************************************************************
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
**************************************************************************
I1016 23:53:26.402] 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:3b3918e49cc32341393723e3557ab783f22af324 --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=quick --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
I1016 23:53:26.402] Bootstrap chewong-e2e-ccm...
I1016 23:53:26.406] Builder: 1b3536c8-f070-11e9-b3d3-b20db476995a
I1016 23:53:26.406] Image: chewong/kubekins-e2e:v20191016-test
I1016 23:53:26.406] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864
I1016 23:53:26.406] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1016 23:53:26.919] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1016 23:53:26.951] process 215 exited with code 0 after 0.0m
I1016 23:53:26.951] Call:  gcloud config get-value account
I1016 23:53:27.195] process 227 exited with code 0 after 0.0m
I1016 23:53:27.195] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1016 23:53:27.196] Root: /go/src
I1016 23:53:27.196] cd to /go/src
I1016 23:53:27.196] Checkout: /go/src/k8s.io/kubernetes release-1.16 to /go/src/k8s.io/kubernetes
I1016 23:53:27.197] Call:  git init k8s.io/kubernetes
I1016 23:53:27.200] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/
I1016 23:53:27.201] process 239 exited with code 0 after 0.0m
I1016 23:53:27.201] Call:  git config --local user.name 'K8S Bootstrap'
I1016 23:53:27.203] process 240 exited with code 0 after 0.0m
I1016 23:53:27.204] Call:  git config --local user.email k8s_bootstrap@localhost
I1016 23:53:27.206] process 241 exited with code 0 after 0.0m
I1016 23:53:27.207] Call:  git fetch --quiet --tags https://github.com/kubernetes/kubernetes release-1.16
I1016 23:54:19.374] process 242 exited with code 0 after 0.9m
I1016 23:54:19.374] Call:  git checkout -B test FETCH_HEAD
W1016 23:54:21.471] Switched to a new branch 'test'
I1016 23:54:21.481] process 254 exited with code 0 after 0.0m
I1016 23:54:21.481] Call:  git show -s --format=format:%ct HEAD
I1016 23:54:21.485] process 255 exited with code 0 after 0.0m
I1016 23:54:21.486] Checkout: /go/src/k8s.io/cloud-provider-azure master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:3b3918e49cc32341393723e3557ab783f22af324 to /go/src/k8s.io/cloud-provider-azure
I1016 23:54:21.486] Call:  git init k8s.io/cloud-provider-azure
I1016 23:54:21.489] Initialized empty Git repository in /go/src/k8s.io/cloud-provider-azure/.git/
I1016 23:54:21.490] process 256 exited with code 0 after 0.0m
I1016 23:54:21.490] Call:  git config --local user.name 'K8S Bootstrap'
I1016 23:54:21.492] process 257 exited with code 0 after 0.0m
I1016 23:54:21.492] Call:  git config --local user.email k8s_bootstrap@localhost
I1016 23:54:21.495] process 258 exited with code 0 after 0.0m
I1016 23:54:21.495] Call:  git fetch --quiet --tags https://github.com/kubernetes/cloud-provider-azure master +refs/pull/248/head:refs/pr/248
I1016 23:54:22.865] process 259 exited with code 0 after 0.0m
I1016 23:54:22.865] Call:  git checkout -B test c470e6f36d76e5a565478fcba22118c06bc1548f
W1016 23:54:23.283] Switched to a new branch 'test'
I1016 23:54:23.288] process 271 exited with code 0 after 0.0m
I1016 23:54:23.288] Call:  git show -s --format=format:%ct HEAD
I1016 23:54:23.291] process 272 exited with code 0 after 0.0m
I1016 23:54:23.291] Call:  git merge --no-ff -m 'Merge +refs/pull/248/head:refs/pr/248' 3b3918e49cc32341393723e3557ab783f22af324
I1016 23:54:23.634] Merge made by the 'recursive' strategy.
I1016 23:54:23.636]  hack/log-dump.sh | 161 +++++++++++++++++++++++++++++++++++++++++++++++++++++++
I1016 23:54:23.637]  1 file changed, 161 insertions(+)
I1016 23:54:23.637]  create mode 100755 hack/log-dump.sh
I1016 23:54:23.637] process 273 exited with code 0 after 0.0m
I1016 23:54:23.637] Configure environment...
I1016 23:54:23.637] Call:  git show -s --format=format:%ct HEAD
I1016 23:54:23.642] process 275 exited with code 0 after 0.0m
I1016 23:54:23.642] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1016 23:54:24.253] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1016 23:54:24.363] process 276 exited with code 0 after 0.0m
I1016 23:54:24.364] Call:  gcloud config get-value account
I1016 23:54:24.601] process 288 exited with code 0 after 0.0m
I1016 23:54:24.601] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1016 23:54:24.602] 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
'
I1016 23:54:24.953] process 300 exited with code 0 after 0.0m
I1016 23:54:24.953] Start 1184618325913636864 at v1.16.3-beta.0.7+36c5c7765e40a8...
I1016 23:54:24.955] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_8Hqng8 gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864/started.json
I1016 23:54:26.329] process 333 exited with code 0 after 0.0m
I1016 23:54:26.329] 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/1184618325913636864' cp /tmp/gsutil_J7cZ8v gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/1184618325913636864.txt
I1016 23:54:27.730] process 511 exited with code 0 after 0.0m
I1016 23:54:27.731] Call:  /workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=quick --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
W1016 23:54:27.771] starts with local mode
W1016 23:54:27.771] Environment:
W1016 23:54:27.771] ARTIFACTS=/workspace/_artifacts
W1016 23:54:27.772] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa
W1016 23:54:27.772] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub
W1016 23:54:27.772] AZURE_CREDENTIALS=/etc/azure-cred/credentials
W1016 23:54:27.772] AZURE_SSH_PRIVATE_KEY_FILE=/etc/ssh-key-secret/ssh-private
W1016 23:54:27.772] AZURE_SSH_PUBLIC_KEY_FILE=/etc/ssh-key-secret/ssh-public
W1016 23:54:27.772] AZURE_SSH_USER=azureuser
W1016 23:54:27.772] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer
W1016 23:54:27.773] BAZEL_REMOTE_CACHE_ENABLED=false
W1016 23:54:27.773] BAZEL_VERSION=0.23.2
W1016 23:54:27.773] BOOTSTRAP_MIGRATION=yes
W1016 23:54:27.773] BUILD_ID=1184618325913636864
W1016 23:54:27.773] BUILD_NUMBER=1184618325913636864
W1016 23:54:27.773] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true
W1016 23:54:27.774] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud
W1016 23:54:27.774] CLOUDSDK_CORE_DISABLE_PROMPTS=1
W1016 23:54:27.774] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false
W1016 23:54:27.774] CLOUD_CONFIG=random
W1016 23:54:27.774] DECK_PORT=tcp://10.0.160.83:80
W1016 23:54:27.774] DECK_PORT_80_TCP=tcp://10.0.160.83:80
W1016 23:54:27.775] DECK_PORT_80_TCP_ADDR=10.0.160.83
W1016 23:54:27.775] DECK_PORT_80_TCP_PORT=80
W1016 23:54:27.775] DECK_PORT_80_TCP_PROTO=tcp
W1016 23:54:27.775] DECK_SERVICE_HOST=10.0.160.83
W1016 23:54:27.775] DECK_SERVICE_PORT=80
W1016 23:54:27.775] DOCKER_IN_DOCKER_ENABLED=true
W1016 23:54:27.776] DOCKER_IN_DOCKER_IPV6_ENABLED=false
W1016 23:54:27.776] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864/artifacts
W1016 23:54:27.776] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json
W1016 23:54:27.776] GOPATH=/go
W1016 23:54:27.776] GO_TARBALL=go1.12.10.linux-amd64.tar.gz
W1016 23:54:27.776] HOME=/workspace
W1016 23:54:27.777] HOOK_PORT=tcp://10.0.144.133:8888
W1016 23:54:27.777] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888
W1016 23:54:27.777] HOOK_PORT_8888_TCP_ADDR=10.0.144.133
W1016 23:54:27.777] HOOK_PORT_8888_TCP_PORT=8888
W1016 23:54:27.777] HOOK_PORT_8888_TCP_PROTO=tcp
W1016 23:54:27.777] HOOK_SERVICE_HOST=10.0.144.133
W1016 23:54:27.778] HOOK_SERVICE_PORT=8888
W1016 23:54:27.778] HOSTNAME=1b3536c8-f070-11e9-b3d3-b20db476995a
W1016 23:54:27.778] IMAGE=chewong/kubekins-e2e:v20191016-test
W1016 23:54:27.778] INSTANCE_PREFIX=bootstrap-e2e
W1016 23:54:27.778] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/etc/ssh-key-secret/ssh-private
W1016 23:54:27.778] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/etc/ssh-key-secret/ssh-public
W1016 23:54:27.778] JOB_NAME=chewong-e2e-ccm
W1016 23:54:27.779] JOB_SPEC={"type":"presubmit","job":"chewong-e2e-ccm","buildid":"1184618325913636864","prowjobid":"1b3536c8-f070-11e9-b3d3-b20db476995a","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"cb19b56831d54d1d31249949318ef0b07bf00df9","base_link":"https://github.com/Azure/kubernetes/commit/cb19b56831d54d1d31249949318ef0b07bf00df9","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"}]}}
W1016 23:54:27.779] JOB_TYPE=presubmit
W1016 23:54:27.779] KUBERNETES_PORT=tcp://10.0.0.1:443
W1016 23:54:27.780] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443
W1016 23:54:27.780] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1
W1016 23:54:27.780] KUBERNETES_PORT_443_TCP_PORT=443
W1016 23:54:27.780] KUBERNETES_PORT_443_TCP_PROTO=tcp
W1016 23:54:27.780] KUBERNETES_SERVICE_HOST=10.0.0.1
W1016 23:54:27.780] KUBERNETES_SERVICE_PORT=443
W1016 23:54:27.781] KUBERNETES_SERVICE_PORT_HTTPS=443
W1016 23:54:27.781] KUBETEST_IN_DOCKER=true
W1016 23:54:27.781] KUBETEST_MANUAL_DUMP=y
W1016 23:54:27.781] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e
W1016 23:54:27.781] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e
W1016 23:54:27.781] KUBE_VERBOSE=0
W1016 23:54:27.781] NODE_NAME=1b3536c8-f070-11e9-b3d3-b20db476995a
W1016 23:54:27.782] 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
W1016 23:54:27.782] PROW_JOB_ID=1b3536c8-f070-11e9-b3d3-b20db476995a
W1016 23:54:27.782] PULL_BASE_REF=master
W1016 23:54:27.782] PULL_BASE_SHA=cb19b56831d54d1d31249949318ef0b07bf00df9
W1016 23:54:27.782] PULL_NUMBER=113
W1016 23:54:27.782] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822
W1016 23:54:27.783] PULL_REFS=master:cb19b56831d54d1d31249949318ef0b07bf00df9,113:879465972041635fd7bc8269da49153b67e63822
W1016 23:54:27.783] PWD=/workspace
W1016 23:54:27.783] REGISTRY=k8sprowinternal.azurecr.io
W1016 23:54:27.783] REPO_NAME=kubernetes
W1016 23:54:27.783] REPO_OWNER=Azure
W1016 23:54:27.783] SHLVL=2
W1016 23:54:27.784] SOURCE_DATE_EPOCH=1571260358
W1016 23:54:27.784] TERM=xterm
W1016 23:54:27.784] TIDE_PORT=tcp://10.0.180.53:80
W1016 23:54:27.784] TIDE_PORT_80_TCP=tcp://10.0.180.53:80
W1016 23:54:27.784] TIDE_PORT_80_TCP_ADDR=10.0.180.53
W1016 23:54:27.784] TIDE_PORT_80_TCP_PORT=80
W1016 23:54:27.784] TIDE_PORT_80_TCP_PROTO=tcp
W1016 23:54:27.785] TIDE_SERVICE_HOST=10.0.180.53
W1016 23:54:27.785] TIDE_SERVICE_PORT=80
W1016 23:54:27.785] USER=prow
W1016 23:54:27.785] WORKSPACE=/workspace
W1016 23:54:27.785] _=./test-infra/jenkins/bootstrap.py
W1016 23:54:27.786] Run: ('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=quick', '--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')
W1016 23:54:27.792] 2019/10/16 23:54:27 main.go:332: Limiting testing to 7h0m0s
W1016 23:54:27.792] 2019/10/16 23:54:27 azure.go:232: Reading credentials file /etc/azure-cred/credentials
W1016 23:54:27.793] 2019/10/16 23:54:27 process.go:153: Running: make -C /go/src/k8s.io/kubernetes quick-release
I1016 23:54:27.893] make: Entering directory '/go/src/k8s.io/kubernetes'
I1016 23:54:27.894] +++ [1016 23:54:27] Verifying Prerequisites....
I1016 23:54:28.088] +++ [1016 23:54:28] Building Docker image kube-build:build-a4d5e9c427-5-v1.12.10-1
I1016 23:57:14.770] +++ [1016 23:57:14] Creating data container kube-build-data-a4d5e9c427-5-v1.12.10-1
I1016 23:57:46.287] +++ [1016 23:57:46] Syncing sources to container
I1016 23:57:53.227] +++ [1016 23:57:53] Running build command...
I1016 23:58:01.385] +++ [1016 23:58:01] Building go targets for linux/amd64:
I1016 23:58:01.385]     ./vendor/k8s.io/code-generator/cmd/deepcopy-gen
I1016 23:58:08.679] +++ [1016 23:58:08] Building go targets for linux/amd64:
I1016 23:58:08.679]     ./vendor/k8s.io/code-generator/cmd/defaulter-gen
I1016 23:58:15.239] +++ [1016 23:58:15] Building go targets for linux/amd64:
I1016 23:58:15.239]     ./vendor/k8s.io/code-generator/cmd/conversion-gen
I1016 23:58:25.817] +++ [1016 23:58:25] Building go targets for linux/amd64:
I1016 23:58:25.817]     ./vendor/k8s.io/kube-openapi/cmd/openapi-gen
I1016 23:58:37.694] +++ [1016 23:58:37] Building go targets for linux/amd64:
I1016 23:58:37.695]     ./vendor/github.com/go-bindata/go-bindata/go-bindata
I1016 23:58:38.922] +++ [1016 23:58:38] Building go targets for linux/amd64:
I1016 23:58:38.922]     cmd/kube-proxy
I1016 23:58:38.923]     cmd/kube-apiserver
I1016 23:58:38.923]     cmd/kube-controller-manager
I1016 23:58:38.923]     cmd/kubelet
I1016 23:58:38.923]     cmd/kubeadm
I1016 23:58:38.923]     cmd/hyperkube
I1016 23:58:38.923]     cmd/kube-scheduler
I1016 23:58:38.923]     vendor/k8s.io/apiextensions-apiserver
I1016 23:58:38.923]     cluster/gce/gci/mounter
I1017 00:02:01.521] +++ [1017 00:02:01] Building go targets for linux/amd64:
I1017 00:02:01.521]     cmd/kube-proxy
I1017 00:02:01.522]     cmd/kubeadm
I1017 00:02:01.522]     cmd/kubelet
I1017 00:02:12.792] +++ [1017 00:02:12] Building go targets for linux/amd64:
I1017 00:02:12.792]     cmd/kubectl
I1017 00:02:29.340] +++ [1017 00:02:29] Building go targets for linux/amd64:
I1017 00:02:29.340]     cmd/gendocs
I1017 00:02:29.341]     cmd/genkubedocs
I1017 00:02:29.341]     cmd/genman
I1017 00:02:29.341]     cmd/genyaml
I1017 00:02:29.341]     cmd/genswaggertypedocs
I1017 00:02:29.341]     cmd/linkcheck
I1017 00:02:29.341]     vendor/github.com/onsi/ginkgo/ginkgo
I1017 00:02:29.342]     test/e2e/e2e.test
I1017 00:02:29.342]     cluster/images/conformance/go-runner
I1017 00:04:17.995] +++ [1017 00:04:17] Building go targets for linux/amd64:
I1017 00:04:17.995]     cmd/kubemark
I1017 00:04:17.995]     vendor/github.com/onsi/ginkgo/ginkgo
I1017 00:04:17.995]     test/e2e_node/e2e_node.test
I1017 00:05:32.373] +++ [1017 00:05:32] Syncing out of container
I1017 00:06:12.450] +++ [1017 00:06:12] Building tarball: manifests
I1017 00:06:12.450] +++ [1017 00:06:12] Building tarball: src
I1017 00:06:12.451] +++ [1017 00:06:12] Starting tarball: client linux-amd64
I1017 00:06:12.453] +++ [1017 00:06:12] Waiting on tarballs
I1017 00:06:18.809] +++ [1017 00:06:18] Building tarball: node linux-amd64
I1017 00:06:18.811] +++ [1017 00:06:18] Building images: linux-amd64
I1017 00:06:19.508] +++ [1017 00:06:19] Starting docker build for image: kube-apiserver-amd64
I1017 00:06:19.510] +++ [1017 00:06:19] Starting docker build for image: kube-controller-manager-amd64
I1017 00:06:19.513] +++ [1017 00:06:19] Starting docker build for image: kube-scheduler-amd64
I1017 00:06:19.515] +++ [1017 00:06:19] Starting docker build for image: kube-proxy-amd64
I1017 00:06:19.523] +++ [1017 00:06:19] Building hyperkube image for arch: amd64
I1017 00:06:19.524] +++ [1017 00:06:19] Building conformance image for arch: amd64
I1017 00:07:05.670] +++ [1017 00:07:05] Deleting docker image k8s.gcr.io/kube-scheduler-amd64:v1.16.3-beta.0.7_36c5c7765e40a8
I1017 00:07:05.889] +++ [1017 00:07:05] Deleting docker image k8s.gcr.io/kube-controller-manager-amd64:v1.16.3-beta.0.7_36c5c7765e40a8
I1017 00:07:05.983] +++ [1017 00:07:05] Deleting docker image k8s.gcr.io/kube-apiserver-amd64:v1.16.3-beta.0.7_36c5c7765e40a8
I1017 00:07:18.394] +++ [1017 00:07:18] Deleting docker image k8s.gcr.io/kube-proxy-amd64:v1.16.3-beta.0.7_36c5c7765e40a8
I1017 00:07:46.105] +++ [1017 00:07:46] Deleting hyperkube image k8s.gcr.io/hyperkube-amd64:v1.16.3-beta.0.7_36c5c7765e40a8
I1017 00:08:16.664] +++ [1017 00:08:16] Deleting conformance image k8s.gcr.io/conformance-amd64:v1.16.3-beta.0.7_36c5c7765e40a8
I1017 00:08:16.881] +++ [1017 00:08:16] Docker builds done
I1017 00:08:16.885] +++ [1017 00:08:16] Building tarball: server linux-amd64
I1017 00:09:42.919] +++ [1017 00:09:42] Building tarball: final
I1017 00:09:43.261] +++ [1017 00:09:43] Waiting on test tarballs
I1017 00:09:43.261] +++ [1017 00:09:43] Starting tarball: test linux-amd64
I1017 00:10:36.109] +++ [1017 00:10:36] Building tarball: test portable
I1017 00:10:36.187] +++ [1017 00:10:36] Building tarball: test mondo (deprecated by KEP sig-testing/20190118-breaking-apart-the-kubernetes-test-tarball)
I1017 00:11:29.582] make: Leaving directory '/go/src/k8s.io/kubernetes'
W1017 00:11:29.682] 2019/10/17 00:11:29 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes quick-release' finished in 17m1.789043781s
W1017 00:11:29.683] 2019/10/17 00:11:29 util.go:277: Flushing memory.
W1017 00:11:37.652] 2019/10/17 00:11:37 azure.go:906: Deleting resource group: kubetest-49dfebea-f070-11e9-804f-024241fcaa24.
W1017 00:11:38.141] 2019/10/17 00:11:38 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1017 00:11:38.141] 2019/10/17 00:11:38 azure.go:673: Attempting Docker login with azure cred.
W1017 00:11:39.469] 2019/10/17 00:11:39 azure.go:682: Docker login success.
W1017 00:11:39.469] 2019/10/17 00:11:39 azure.go:697: Building ccm.
W1017 00:11:39.470] 2019/10/17 00:11:39 azure.go:699: projectPath /go/src/k8s.io/cloud-provider-azure
W1017 00:11:39.470] 2019/10/17 00:11:39 process.go:153: Running: docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184618325913636864-b00298c2 .
I1017 00:11:41.577] Sending build context to Docker daemon  67.18MB

I1017 00:11:41.599] Step 1/7 : FROM golang:1.12.9-stretch AS build
I1017 00:11:42.511] 1.12.9-stretch: Pulling from library/golang
I1017 00:11:42.841] 092586df9206: Pulling fs layer
I1017 00:11:42.841] ef599477fae0: Pulling fs layer
I1017 00:11:42.841] 4530c6472b5d: Pulling fs layer
I1017 00:11:42.842] d34d61487075: Pulling fs layer
I1017 00:11:42.842] 89c6ec31b9e9: Pulling fs layer
I1017 00:11:42.842] e37857ebcafa: Pulling fs layer
I1017 00:11:42.842] b0e29f6c7f0a: Pulling fs layer
I1017 00:11:42.843] d34d61487075: Waiting
I1017 00:11:42.843] 89c6ec31b9e9: Waiting
I1017 00:11:42.843] e37857ebcafa: Waiting
I1017 00:11:42.843] b0e29f6c7f0a: Waiting
I1017 00:11:43.314] 4530c6472b5d: Verifying Checksum
I1017 00:11:43.314] 4530c6472b5d: Download complete
I1017 00:11:43.357] ef599477fae0: Verifying Checksum
I1017 00:11:43.357] ef599477fae0: Download complete
I1017 00:11:43.607] 092586df9206: Verifying Checksum
I1017 00:11:43.607] 092586df9206: Download complete
I1017 00:11:44.156] d34d61487075: Verifying Checksum
I1017 00:11:44.157] d34d61487075: Download complete
I1017 00:11:44.294] 89c6ec31b9e9: Verifying Checksum
I1017 00:11:44.295] 89c6ec31b9e9: Download complete
I1017 00:11:44.531] b0e29f6c7f0a: Download complete
I1017 00:11:45.205] e37857ebcafa: Verifying Checksum
I1017 00:11:45.205] e37857ebcafa: Download complete
I1017 00:11:46.853] 092586df9206: Pull complete
I1017 00:11:47.626] ef599477fae0: Pull complete
I1017 00:11:47.966] 4530c6472b5d: Pull complete
I1017 00:11:51.642] d34d61487075: Pull complete
I1017 00:11:55.091] 89c6ec31b9e9: Pull complete
I1017 00:12:02.517] e37857ebcafa: Pull complete
I1017 00:12:02.674] b0e29f6c7f0a: Pull complete
I1017 00:12:02.698] Digest: sha256:76b52857546f070cc3ac499accb27b8c411b10ff6d45c0b1da2a8aab7b61fe29
I1017 00:12:02.717] Status: Downloaded newer image for golang:1.12.9-stretch
I1017 00:12:02.718]  ---> 2c4a601e5da9
I1017 00:12:02.718] Step 2/7 : WORKDIR /go/src/k8s.io/cloud-provider-azure
I1017 00:12:14.704]  ---> Running in 8261a35d3316
I1017 00:12:15.872] Removing intermediate container 8261a35d3316
I1017 00:12:15.872]  ---> 2ec868eca7fe
I1017 00:12:15.873] Step 3/7 : COPY . .
I1017 00:12:21.742]  ---> 698a926a1006
I1017 00:12:21.743] Step 4/7 : RUN make
I1017 00:12:21.966]  ---> Running in 53cc5747c2b4
I1017 00:12:22.739] hack/pkg-config.sh > .pkg_config
I1017 00:12:22.763] go build -o bin/azure-cloud-controller-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-11-g694146193 -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=694146193d5bc1e5cc34d766cc2c9c2f8de86331 -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-17T00:12:22Z' ./cmd/cloud-controller-manager
I1017 00:13:04.908] go build -o bin/azure-cloud-node-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-11-g694146193 -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=694146193d5bc1e5cc34d766cc2c9c2f8de86331 -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-17T00:12:22Z' ./cmd/cloud-node-manager
I1017 00:13:28.813] Removing intermediate container 53cc5747c2b4
I1017 00:13:28.814]  ---> e666ea73eabf
I1017 00:13:28.814] Step 5/7 : FROM k8s.gcr.io/debian-base:v1.0.0
I1017 00:13:29.104] v1.0.0: Pulling from debian-base
I1017 00:13:29.272] Digest: sha256:3801f944c765dc1b54900826ca67b1380bb8c73b9caf4a2a27ce613b3ba3e742
I1017 00:13:30.527] Status: Downloaded newer image for k8s.gcr.io/debian-base:v1.0.0
I1017 00:13:30.527]  ---> 204e96332c91
I1017 00:13:30.528] Step 6/7 : COPY --from=build /go/src/k8s.io/cloud-provider-azure/bin/azure-cloud-controller-manager /usr/local/bin
I1017 00:13:32.820]  ---> 26cf34a86dc3
I1017 00:13:32.820] Step 7/7 : RUN ln -s /usr/local/bin/azure-cloud-controller-manager /usr/local/bin/cloud-controller-manager
I1017 00:13:32.964]  ---> Running in a483a2680510
I1017 00:13:35.060] Removing intermediate container a483a2680510
I1017 00:13:35.060]  ---> 098af8fdfd6e
I1017 00:13:35.164] Successfully built 098af8fdfd6e
I1017 00:13:35.562] Successfully tagged k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184618325913636864-b00298c2
W1017 00:13:35.663] 2019/10/17 00:13:35 process.go:155: Step 'docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184618325913636864-b00298c2 .' finished in 1m56.097472678s
W1017 00:13:35.663] 2019/10/17 00:13:35 process.go:153: Running: docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184618325913636864-b00298c2
W1017 00:13:39.677] 2019/10/17 00:13:39 process.go:155: Step 'docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184618325913636864-b00298c2' finished in 4.109957289s
W1017 00:13:39.677] 2019/10/17 00:13:39 azure.go:686: Docker logout.
W1017 00:13:39.736] 2019/10/17 00:13:39 azure.go:716: Custom cloud controller manager URL: k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184618325913636864-b00298c2 .
W1017 00:13:39.737] 2019/10/17 00:13:39 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1017 00:13:39.737] 2019/10/17 00:13:39 azure.go:673: Attempting Docker login with azure cred.
W1017 00:13:40.668] 2019/10/17 00:13:40 azure.go:682: Docker login success.
W1017 00:13:40.668] 2019/10/17 00:13:40 azure.go:726: Building hyperkube.
W1017 00:13:40.668] 2019/10/17 00:13:40 process.go:153: Running: make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube
W1017 00:16:31.904] 2019/10/17 00:16:31 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube' finished in 2m51.236183454s
W1017 00:16:31.904] 2019/10/17 00:16:31 azure.go:733: Pushing hyperkube.
W1017 00:16:31.905] 2019/10/17 00:16:31 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 00:16:32.005] make: Entering directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
I1017 00:16:32.005] cp -r ./* /tmp/hyperkubeA7Lt7c
I1017 00:16:32.040] cp /go/src/k8s.io/kubernetes/_output/bin/hyperkube /tmp/hyperkubeA7Lt7c
I1017 00:16:32.211] chmod a+rx /tmp/hyperkubeA7Lt7c/hyperkube
I1017 00:16:32.213] cd /tmp/hyperkubeA7Lt7c && sed -i.back "s|BASEIMAGE|k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1|g" Dockerfile
I1017 00:16:32.215] docker build --pull -t k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184618325913636864-f87ca5f5 /tmp/hyperkubeA7Lt7c
I1017 00:16:33.364] Sending build context to Docker daemon  212.1MB

I1017 00:16:33.392] Step 1/2 : FROM k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1017 00:16:33.710] 0.12.1: Pulling from debian-hyperkube-base-amd64
I1017 00:16:33.711] Digest: sha256:5d4ea2fb5fbe9a9a9da74f67cf2faefc881968bc39f2ac5d62d9167e575812a1
I1017 00:16:33.712] Status: Image is up to date for k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1017 00:16:33.712]  ---> a46476511725
I1017 00:16:33.712] Step 2/2 : COPY hyperkube /hyperkube
I1017 00:16:54.260]  ---> 7c203878c656
I1017 00:16:54.286] Successfully built 7c203878c656
I1017 00:16:54.370] Successfully tagged k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184618325913636864-f87ca5f5
I1017 00:16:54.372] rm -rf "/tmp/hyperkubeA7Lt7c"
I1017 00:16:54.401] docker push k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184618325913636864-f87ca5f5
I1017 00:16:54.463] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube-amd64]
I1017 00:16:54.475] cbc53b2ad765: Preparing
I1017 00:16:54.476] 39b3ac6d96e9: Preparing
I1017 00:16:54.476] 7bbae4dddb88: Preparing
I1017 00:16:54.476] a00defcfe869: Preparing
I1017 00:16:54.476] 2ab0ae805c74: Preparing
I1017 00:16:54.476] 43a8fe7d2382: Preparing
I1017 00:16:54.476] 3f6a6f542637: Preparing
I1017 00:16:54.476] 5ba3be777c2d: Preparing
I1017 00:16:54.477] 43a8fe7d2382: Waiting
I1017 00:16:54.477] 3f6a6f542637: Waiting
I1017 00:16:54.477] 5ba3be777c2d: Waiting
I1017 00:16:54.641] 39b3ac6d96e9: Layer already exists
I1017 00:16:54.663] a00defcfe869: Layer already exists
I1017 00:16:54.685] 2ab0ae805c74: Layer already exists
I1017 00:16:54.708] 7bbae4dddb88: Layer already exists
I1017 00:16:54.745] 3f6a6f542637: Layer already exists
I1017 00:16:54.821] 5ba3be777c2d: Layer already exists
I1017 00:16:54.844] 43a8fe7d2382: Layer already exists
I1017 00:17:04.649] cbc53b2ad765: Pushed
I1017 00:17:06.496] azure-e2e-1184618325913636864-f87ca5f5: digest: sha256:947c20b3d417e3fcc59f48861190fe9447eb06bdafa57baf37cb7fa2d82461b4 size: 1998
I1017 00:17:06.516] docker rmi k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184618325913636864-f87ca5f5 2>/dev/null || true
I1017 00:17:06.561] docker tag k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184618325913636864-f87ca5f5 k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184618325913636864-f87ca5f5
I1017 00:17:06.627] docker push k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184618325913636864-f87ca5f5
I1017 00:17:06.687] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube]
I1017 00:17:06.699] cbc53b2ad765: Preparing
I1017 00:17:06.700] 39b3ac6d96e9: Preparing
I1017 00:17:06.700] 7bbae4dddb88: Preparing
I1017 00:17:06.700] a00defcfe869: Preparing
I1017 00:17:06.700] 2ab0ae805c74: Preparing
I1017 00:17:06.700] 43a8fe7d2382: Preparing
I1017 00:17:06.700] 3f6a6f542637: Preparing
I1017 00:17:06.700] 5ba3be777c2d: Preparing
I1017 00:17:06.700] 3f6a6f542637: Waiting
I1017 00:17:06.701] 5ba3be777c2d: Waiting
I1017 00:17:06.701] 43a8fe7d2382: Waiting
I1017 00:17:06.790] 2ab0ae805c74: Layer already exists
I1017 00:17:06.813] a00defcfe869: Layer already exists
I1017 00:17:06.834] 7bbae4dddb88: Layer already exists
I1017 00:17:06.868] 39b3ac6d96e9: Layer already exists
I1017 00:17:06.893] 43a8fe7d2382: Layer already exists
I1017 00:17:06.904] 3f6a6f542637: Layer already exists
I1017 00:17:06.914] cbc53b2ad765: Mounted from hyperkube-amd64
I1017 00:17:06.927] 5ba3be777c2d: Layer already exists
I1017 00:17:08.253] azure-e2e-1184618325913636864-f87ca5f5: digest: sha256:947c20b3d417e3fcc59f48861190fe9447eb06bdafa57baf37cb7fa2d82461b4 size: 1998
I1017 00:17:08.268] make: Leaving directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
W1017 00:17:08.369] 2019/10/17 00:17:08 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 36.364523362s
W1017 00:17:08.369] 2019/10/17 00:17:08 azure.go:686: Docker logout.
W1017 00:17:08.369] 2019/10/17 00:17:08 azure.go:744: Custom hyperkube URL: k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184618325913636864-f87ca5f5 .
W1017 00:17:08.369] 2019/10/17 00:17:08 azure.go:787: downloading /workspace/aks763108785/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json.
W1017 00:17:08.370] 2019/10/17 00:17:08 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json
W1017 00:17:08.504] 2019/10/17 00:17:08 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 00:17:08.504] 2019/10/17 00:17:08 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 00:17:09.755] 2019/10/17 00:17:09 azure.go:556: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes .
W1017 00:17:09.756] 2019/10/17 00:17:09 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1
W1017 00:17:09.906] 2019/10/17 00:17:09 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 151.15808ms
W1017 00:17:09.907] 2019/10/17 00:17:09 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks763108785/kubernetes.json --output-directory /workspace/aks763108785
I1017 00:17:10.102] INFO[0000] Generating assets into /workspace/aks763108785... 
W1017 00:17:18.284] 2019/10/17 00:17:18 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks763108785/kubernetes.json --output-directory /workspace/aks763108785' finished in 8.377574598s
W1017 00:17:18.288] 2019/10/17 00:17:18 azure.go:627: Setting kubeconfig env variable: kubeconfig path: /workspace/aks763108785/kubeconfig/kubeconfig.eastus2.json.
W1017 00:17:18.288] 2019/10/17 00:17:18 azure.go:629: Creating resource group: kubetest-49dfebea-f070-11e9-804f-024241fcaa24.
W1017 00:17:18.289] 2019/10/17 00:17:18 azure.go:631: Creating Azure resource group: kubetest-49dfebea-f070-11e9-804f-024241fcaa24 for cluster deployment.
W1017 00:17:19.854] 2019/10/17 00:17:19 azure.go:636: Validating deployment ARM templates.
W1017 00:17:22.177] 2019/10/17 00:17:22 azure.go:642: Deploying cluster kubetest-49dfebea-f070-11e9-804f-024241fcaa24 in resource group kubetest-49dfebea-f070-11e9-804f-024241fcaa24.
W1017 00:30:44.904] 2019/10/17 00:30:44 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version
W1017 00:30:45.543] 2019/10/17 00:30:45 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 639.390967ms
W1017 00:30:45.544] 2019/10/17 00:30:45 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false get nodes -oyaml
W1017 00:30:47.113] 2019/10/17 00:30:47 process.go:155: Step './cluster/kubectl.sh --match-server-version=false get nodes -oyaml' finished in 1.569558292s
W1017 00:30:47.113] 2019/10/17 00:30:47 azure.go:962: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos.
W1017 00:30:47.114] 2019/10/17 00:30:47 azure.go:962: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos.
W1017 00:30:47.114] 2019/10/17 00:30:47 process.go:153: Running: kubectl get nodes --no-headers
W1017 00:30:47.949] 2019/10/17 00:30:47 process.go:155: Step 'kubectl get nodes --no-headers' finished in 835.887793ms
W1017 00:30:47.949] 2019/10/17 00:30:47 e2e.go:462: Cluster nodes:
W1017 00:30:47.950] k8s-agentpool1-27500699-0   Ready   agent    43s   v1.16.3-beta.0.7+36c5c7765e40a8
W1017 00:30:47.950] k8s-master-27500699-0       Ready   master   79s   v1.16.3-beta.0.7+36c5c7765e40a8
W1017 00:30:47.950] 2019/10/17 00:30:47 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version
W1017 00:30:48.360] 2019/10/17 00:30:48 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 411.203494ms
W1017 00:30:48.361] 2019/10/17 00:30:48 azure.go:916: Attempting to dump logs to /workspace/_artifacts
W1017 00:30:48.361] 2019/10/17 00:30:48 process.go:153: Running: bash -c hack/log-dump.sh /workspace/_artifacts
W1017 00:30:48.363] ++ command -v kubectl
W1017 00:30:48.364] ++ [[ -z /etc/ssh-key-secret/ssh-private ]]
W1017 00:30:48.364] ++ [[ -z azureuser ]]
W1017 00:30:48.364] ++ master_logfiles=('kube-apiserver' 'kube-scheduler' 'kube-controller-manager' 'kube-addon-manager' 'cloud-controller-manager')
W1017 00:30:48.364] ++ readonly master_logfiles
W1017 00:30:48.364] ++ node_logfiles=('csi-azuredisk' 'csi-azurefile' 'kube-proxy')
W1017 00:30:48.365] ++ readonly node_logfiles
W1017 00:30:48.365] ++ systemd_services=('kubelet' 'docker' 'etcd')
W1017 00:30:48.365] ++ readonly systemd_services
W1017 00:30:48.365] ++ readonly 'report_dir=\/workspace\/_artifacts'
W1017 00:30:48.365] ++ report_dir='\/workspace\/_artifacts'
W1017 00:30:48.366] ++ main
W1017 00:30:48.366] ++ dump-masters
W1017 00:30:48.366] ++ master_names=($(kubectl get nodes -l kubernetes.io/role=master -ojsonpath={.items[*].metadata.name}))
W1017 00:30:48.366] +++ kubectl get nodes -l kubernetes.io/role=master '-ojsonpath={.items[*].metadata.name}'
W1017 00:30:49.023] ++ local -r master_names
W1017 00:30:49.024] ++ for master_name in "${master_names[@]}"
W1017 00:30:49.024] +++ get-host k8s-master-27500699-0 true
W1017 00:30:49.024] +++ local -r node_name=k8s-master-27500699-0
W1017 00:30:49.024] +++ local -r is_master=true
W1017 00:30:49.024] +++ [[ true == \t\r\u\e ]]
W1017 00:30:49.025] ++++ kubectl config view --minify '-ojsonpath={.clusters[0].cluster.server}'
W1017 00:30:49.025] ++++ sed -e 's/https\:\/\///'
W1017 00:30:49.083] +++ echo kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com
W1017 00:30:49.084] ++ local master_host=kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com
W1017 00:30:49.084] ++ [[ -z kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com ]]
W1017 00:30:49.084] +++ printf '/var/log/containers/%s*,' kube-apiserver kube-scheduler kube-controller-manager kube-addon-manager cloud-controller-manager
W1017 00:30:49.085] ++ local 'master_logfiles_batch={/var/log/containers/kube-apiserver*,/var/log/containers/kube-scheduler*,/var/log/containers/kube-controller-manager*,/var/log/containers/kube-addon-manager*,/var/log/containers/cloud-controller-manager*,}'
W1017 00:30:49.085] ++ log-dump-ssh kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com 'sudo cp {/var/log/containers/kube-apiserver*,/var/log/containers/kube-scheduler*,/var/log/containers/kube-controller-manager*,/var/log/containers/kube-addon-manager*,/var/log/containers/cloud-controller-manager*,} /var/log'
W1017 00:30:49.085] ++ local -r host=kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com
W1017 00:30:49.085] ++ local -r 'cmd=sudo cp {/var/log/containers/kube-apiserver*,/var/log/containers/kube-scheduler*,/var/log/containers/kube-controller-manager*,/var/log/containers/kube-addon-manager*,/var/log/containers/cloud-controller-manager*,} /var/log'
W1017 00:30:49.086] ++ [[ -z kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com ]]
W1017 00:30:49.086] ++ [[ -z sudo cp {/var/log/containers/kube-apiserver*,/var/log/containers/kube-scheduler*,/var/log/containers/kube-controller-manager*,/var/log/containers/kube-addon-manager*,/var/log/containers/cloud-controller-manager*,} /var/log ]]
W1017 00:30:49.086] ++ ssh -oConnectTimeout=30 -oStrictHostKeyChecking=no -i /etc/ssh-key-secret/ssh-private azureuser@kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com 'sudo cp {/var/log/containers/kube-apiserver*,/var/log/containers/kube-scheduler*,/var/log/containers/kube-controller-manager*,/var/log/containers/kube-addon-manager*,/var/log/containers/cloud-controller-manager*,} /var/log'
W1017 00:31:19.145] ssh: connect to host kubetest-49dfebea-f070-11e9-804f-024241fcaa24.eastus2.cloudapp.azure.com port 22: Connection timed out
W1017 00:31:19.147] 2019/10/17 00:31:19 process.go:155: Step 'bash -c hack/log-dump.sh /workspace/_artifacts' finished in 30.786109126s
W1017 00:31:19.147] 2019/10/17 00:31:19 azure.go:906: Deleting resource group: kubetest-49dfebea-f070-11e9-804f-024241fcaa24.
W1017 00:42:41.286] 2019/10/17 00:42:41 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml.
W1017 00:42:41.287] 2019/10/17 00:42:41 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
W1017 00:42:41.435] 2019/10/17 00:42:41 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 148.042823ms
W1017 00:42:41.435] 2019/10/17 00:42:41 main.go:319: Something went wrong: encountered 1 errors: [error during bash -c hack/log-dump.sh /workspace/_artifacts: exit status 255]
W1017 00:42:41.436] Traceback (most recent call last):
W1017 00:42:41.437]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module>
W1017 00:42:41.437]     main(parse_args())
W1017 00:42:41.437]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main
W1017 00:42:41.438]     mode.start(runner_args)
W1017 00:42:41.438]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start
W1017 00:42:41.438]     check_env(env, self.command, *args)
W1017 00:42:41.438]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env
W1017 00:42:41.438]     subprocess.check_call(cmd, env=env)
W1017 00:42:41.438]   File "/usr/lib/python2.7/subprocess.py", line 186, in check_call
W1017 00:42:41.439]     raise CalledProcessError(retcode, cmd)
W1017 00:42:41.439] subprocess.CalledProcessError: Command '('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=quick', '--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 00:42:41.444] Command failed
I1017 00:42:41.444] process 689 exited with code 1 after 48.2m
E1017 00:42:41.445] FAIL: chewong-e2e-ccm
I1017 00:42:41.445] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1017 00:42:42.257] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1017 00:42:42.287] process 18039 exited with code 0 after 0.0m
I1017 00:42:42.288] Call:  gcloud config get-value account
I1017 00:42:42.537] process 18051 exited with code 0 after 0.0m
I1017 00:42:42.537] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1017 00:42:42.537] Upload result and artifacts...
I1017 00:42:42.537] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864
I1017 00:42:42.538] Call:  gsutil ls gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864/artifacts
W1017 00:42:43.729] CommandException: One or more URLs matched no objects.
E1017 00:42:43.807] Command failed
I1017 00:42:43.808] process 18063 exited with code 1 after 0.0m
W1017 00:42:43.808] Remote dir gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864/artifacts not exist yet
I1017 00:42:43.808] 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/1184618325913636864/artifacts
I1017 00:42:45.362] process 18205 exited with code 0 after 0.0m
I1017 00:42:45.362] Call:  git rev-parse HEAD
I1017 00:42:45.365] process 18732 exited with code 0 after 0.0m
I1017 00:42:45.365] Call:  git rev-parse HEAD
I1017 00:42:45.368] process 18733 exited with code 0 after 0.0m
I1017 00:42:45.368] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1017 00:42:46.347] process 18734 exited with code 0 after 0.0m
I1017 00:42:46.348] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json#1571269611954422'
I1017 00:42:47.714] process 18876 exited with code 0 after 0.0m
I1017 00:42:47.715] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571269611954422 cp /tmp/gsutil_avEcZ8 gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1017 00:42:49.067] process 19020 exited with code 0 after 0.0m
I1017 00:42:49.068] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1017 00:42:50.047] process 19198 exited with code 0 after 0.0m
I1017 00:42:50.048] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json#1571269615417460'
I1017 00:42:51.335] process 19340 exited with code 0 after 0.0m
I1017 00:42:51.335] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571269615417460 cp /tmp/gsutil_Vmvire gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1017 00:42:52.797] process 19484 exited with code 0 after 0.0m
I1017 00:42:52.798] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_oInKqy gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184618325913636864/finished.json
I1017 00:42:54.091] process 19662 exited with code 0 after 0.0m
I1017 00:42:54.091] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_diTwAl gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/latest-build.txt
I1017 00:42:55.617] process 19840 exited with code 0 after 0.0m
I1017 00:42:55.617] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_LllpQd gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/latest-build.txt
I1017 00:42:56.971] process 20018 exited with code 0 after 0.0m