W1015 21:10:25.671] **************************************************************************
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
**************************************************************************
I1015 21:10:25.671] 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=master --repo=k8s.io/cloud-provider-azure=master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:95c5c01d4ae3237e932ed7bae98f82bd66987c26 --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.36.5/aks-engine-v0.36.5-linux-amd64.tar.gz --timeout=420m
I1015 21:10:25.671] Bootstrap chewong-e2e-ccm...
I1015 21:10:25.675] Builder: 2410a326-ef90-11e9-918b-16773c0c7aed
I1015 21:10:25.675] Image: chewong/kubekins-e2e:v20191014-test
I1015 21:10:25.676] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432
I1015 21:10:25.676] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1015 21:10:26.208] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1015 21:10:26.237] process 213 exited with code 0 after 0.0m
I1015 21:10:26.238] Call:  gcloud config get-value account
I1015 21:10:26.474] process 225 exited with code 0 after 0.0m
I1015 21:10:26.474] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1015 21:10:26.475] Root: /go/src
I1015 21:10:26.475] cd to /go/src
I1015 21:10:26.475] Checkout: /go/src/k8s.io/kubernetes master to /go/src/k8s.io/kubernetes
I1015 21:10:26.475] Call:  git init k8s.io/kubernetes
I1015 21:10:26.479] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/
I1015 21:10:26.479] process 237 exited with code 0 after 0.0m
I1015 21:10:26.480] Call:  git config --local user.name 'K8S Bootstrap'
I1015 21:10:26.482] process 238 exited with code 0 after 0.0m
I1015 21:10:26.482] Call:  git config --local user.email k8s_bootstrap@localhost
I1015 21:10:26.485] process 239 exited with code 0 after 0.0m
I1015 21:10:26.485] Call:  git fetch --quiet --tags https://github.com/kubernetes/kubernetes master
I1015 21:11:18.746] process 240 exited with code 0 after 0.9m
I1015 21:11:18.746] Call:  git checkout -B test FETCH_HEAD
W1015 21:11:20.863] Switched to a new branch 'test'
I1015 21:11:20.871] process 255 exited with code 0 after 0.0m
I1015 21:11:20.871] Call:  git show -s --format=format:%ct HEAD
I1015 21:11:20.874] process 256 exited with code 0 after 0.0m
I1015 21:11:20.875] Checkout: /go/src/k8s.io/cloud-provider-azure master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:95c5c01d4ae3237e932ed7bae98f82bd66987c26 to /go/src/k8s.io/cloud-provider-azure
I1015 21:11:20.875] Call:  git init k8s.io/cloud-provider-azure
I1015 21:11:20.878] Initialized empty Git repository in /go/src/k8s.io/cloud-provider-azure/.git/
I1015 21:11:20.878] process 257 exited with code 0 after 0.0m
I1015 21:11:20.879] Call:  git config --local user.name 'K8S Bootstrap'
I1015 21:11:20.881] process 258 exited with code 0 after 0.0m
I1015 21:11:20.881] Call:  git config --local user.email k8s_bootstrap@localhost
I1015 21:11:20.884] process 259 exited with code 0 after 0.0m
I1015 21:11:20.884] Call:  git fetch --quiet --tags https://github.com/kubernetes/cloud-provider-azure master +refs/pull/248/head:refs/pr/248
I1015 21:11:22.537] process 260 exited with code 0 after 0.0m
I1015 21:11:22.537] Call:  git checkout -B test c470e6f36d76e5a565478fcba22118c06bc1548f
W1015 21:11:22.950] Switched to a new branch 'test'
I1015 21:11:22.952] process 272 exited with code 0 after 0.0m
I1015 21:11:22.952] Call:  git show -s --format=format:%ct HEAD
I1015 21:11:22.955] process 273 exited with code 0 after 0.0m
I1015 21:11:22.956] Call:  git merge --no-ff -m 'Merge +refs/pull/248/head:refs/pr/248' 95c5c01d4ae3237e932ed7bae98f82bd66987c26
I1015 21:11:23.287] Merge made by the 'recursive' strategy.
I1015 21:11:23.289]  hack/log-dump.sh | 161 +++++++++++++++++++++++++++++++++++++++++++++++++++++++
I1015 21:11:23.289]  1 file changed, 161 insertions(+)
I1015 21:11:23.289]  create mode 100755 hack/log-dump.sh
I1015 21:11:23.289] process 274 exited with code 0 after 0.0m
I1015 21:11:23.289] Configure environment...
I1015 21:11:23.289] Call:  git show -s --format=format:%ct HEAD
I1015 21:11:23.292] process 276 exited with code 0 after 0.0m
I1015 21:11:23.292] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1015 21:11:24.025] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1015 21:11:24.134] process 277 exited with code 0 after 0.0m
I1015 21:11:24.134] Call:  gcloud config get-value account
I1015 21:11:24.372] process 289 exited with code 0 after 0.0m
I1015 21:11:24.372] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1015 21:11:24.372] 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
'
I1015 21:11:24.907] process 301 exited with code 0 after 0.0m
I1015 21:11:24.908] Start 1184214917721362432 at v1.17.0-alpha.2.11+6b63df2dc4634a...
I1015 21:11:24.910] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_mkliSS gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432/started.json
I1015 21:11:26.434] process 334 exited with code 0 after 0.0m
I1015 21:11:26.435] 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/1184214917721362432' cp /tmp/gsutil_pR1M9P gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/1184214917721362432.txt
I1015 21:11:27.717] process 512 exited with code 0 after 0.0m
I1015 21:11:27.718] 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/azure-ssh/azure-ssh-pub --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.36.5/aks-engine-v0.36.5-linux-amd64.tar.gz --timeout=420m
W1015 21:11:27.756] starts with local mode
W1015 21:11:27.756] Environment:
W1015 21:11:27.756] ARTIFACTS=/workspace/_artifacts
W1015 21:11:27.757] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa
W1015 21:11:27.757] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub
W1015 21:11:27.757] AZURE_CREDENTIALS=/etc/azure-cred/credentials
W1015 21:11:27.757] AZURE_SSH_PRIVATE_KEY_FILE=/etc/azure-ssh/azure-ssh
W1015 21:11:27.757] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub
W1015 21:11:27.757] AZURE_SSH_USER=azureuser
W1015 21:11:27.758] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer
W1015 21:11:27.758] BAZEL_REMOTE_CACHE_ENABLED=false
W1015 21:11:27.758] BAZEL_VERSION=0.23.2
W1015 21:11:27.758] BOOTSTRAP_MIGRATION=yes
W1015 21:11:27.758] BUILD_ID=1184214917721362432
W1015 21:11:27.758] BUILD_NUMBER=1184214917721362432
W1015 21:11:27.758] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true
W1015 21:11:27.758] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud
W1015 21:11:27.759] CLOUDSDK_CORE_DISABLE_PROMPTS=1
W1015 21:11:27.759] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false
W1015 21:11:27.759] CLOUD_CONFIG=random
W1015 21:11:27.759] DECK_PORT=tcp://10.0.160.83:80
W1015 21:11:27.759] DECK_PORT_80_TCP=tcp://10.0.160.83:80
W1015 21:11:27.759] DECK_PORT_80_TCP_ADDR=10.0.160.83
W1015 21:11:27.759] DECK_PORT_80_TCP_PORT=80
W1015 21:11:27.760] DECK_PORT_80_TCP_PROTO=tcp
W1015 21:11:27.760] DECK_SERVICE_HOST=10.0.160.83
W1015 21:11:27.760] DECK_SERVICE_PORT=80
W1015 21:11:27.760] DOCKER_IN_DOCKER_ENABLED=true
W1015 21:11:27.760] DOCKER_IN_DOCKER_IPV6_ENABLED=false
W1015 21:11:27.760] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432/artifacts
W1015 21:11:27.760] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json
W1015 21:11:27.761] GOPATH=/go
W1015 21:11:27.761] GO_TARBALL=go1.12.1.linux-amd64.tar.gz
W1015 21:11:27.761] HOME=/workspace
W1015 21:11:27.761] HOOK_PORT=tcp://10.0.144.133:8888
W1015 21:11:27.761] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888
W1015 21:11:27.761] HOOK_PORT_8888_TCP_ADDR=10.0.144.133
W1015 21:11:27.761] HOOK_PORT_8888_TCP_PORT=8888
W1015 21:11:27.762] HOOK_PORT_8888_TCP_PROTO=tcp
W1015 21:11:27.762] HOOK_SERVICE_HOST=10.0.144.133
W1015 21:11:27.762] HOOK_SERVICE_PORT=8888
W1015 21:11:27.762] HOSTNAME=2410a326-ef90-11e9-918b-16773c0c7aed
W1015 21:11:27.762] IMAGE=chewong/kubekins-e2e:v20191014-test
W1015 21:11:27.762] INSTANCE_PREFIX=bootstrap-e2e
W1015 21:11:27.762] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine
W1015 21:11:27.763] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub
W1015 21:11:27.763] JOB_NAME=chewong-e2e-ccm
W1015 21:11:27.763] JOB_SPEC={"type":"presubmit","job":"chewong-e2e-ccm","buildid":"1184214917721362432","prowjobid":"2410a326-ef90-11e9-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"6b63df2dc4634a62486a868c82e8cea1420793b3","base_link":"https://github.com/Azure/kubernetes/commit/6b63df2dc4634a62486a868c82e8cea1420793b3","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"}]}}
W1015 21:11:27.764] JOB_TYPE=presubmit
W1015 21:11:27.764] KUBERNETES_PORT=tcp://10.0.0.1:443
W1015 21:11:27.764] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443
W1015 21:11:27.764] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1
W1015 21:11:27.764] KUBERNETES_PORT_443_TCP_PORT=443
W1015 21:11:27.764] KUBERNETES_PORT_443_TCP_PROTO=tcp
W1015 21:11:27.764] KUBERNETES_SERVICE_HOST=10.0.0.1
W1015 21:11:27.765] KUBERNETES_SERVICE_PORT=443
W1015 21:11:27.765] KUBERNETES_SERVICE_PORT_HTTPS=443
W1015 21:11:27.765] KUBETEST_IN_DOCKER=true
W1015 21:11:27.765] KUBETEST_MANUAL_DUMP=y
W1015 21:11:27.765] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e
W1015 21:11:27.765] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e
W1015 21:11:27.765] KUBE_VERBOSE=0
W1015 21:11:27.766] NODE_NAME=2410a326-ef90-11e9-918b-16773c0c7aed
W1015 21:11:27.766] 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
W1015 21:11:27.766] PROW_JOB_ID=2410a326-ef90-11e9-918b-16773c0c7aed
W1015 21:11:27.766] PULL_BASE_REF=master
W1015 21:11:27.766] PULL_BASE_SHA=6b63df2dc4634a62486a868c82e8cea1420793b3
W1015 21:11:27.766] PULL_NUMBER=113
W1015 21:11:27.766] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822
W1015 21:11:27.767] PULL_REFS=master:6b63df2dc4634a62486a868c82e8cea1420793b3,113:879465972041635fd7bc8269da49153b67e63822
W1015 21:11:27.767] PWD=/workspace
W1015 21:11:27.767] REGISTRY=k8sprowinternal.azurecr.io
W1015 21:11:27.767] REPO_NAME=kubernetes
W1015 21:11:27.767] REPO_OWNER=Azure
W1015 21:11:27.767] SHLVL=2
W1015 21:11:27.767] SOURCE_DATE_EPOCH=1571172886
W1015 21:11:27.767] TERM=xterm
W1015 21:11:27.768] TIDE_PORT=tcp://10.0.180.53:80
W1015 21:11:27.768] TIDE_PORT_80_TCP=tcp://10.0.180.53:80
W1015 21:11:27.768] TIDE_PORT_80_TCP_ADDR=10.0.180.53
W1015 21:11:27.768] TIDE_PORT_80_TCP_PORT=80
W1015 21:11:27.768] TIDE_PORT_80_TCP_PROTO=tcp
W1015 21:11:27.768] TIDE_SERVICE_HOST=10.0.180.53
W1015 21:11:27.768] TIDE_SERVICE_PORT=80
W1015 21:11:27.769] WORKSPACE=/workspace
W1015 21:11:27.769] _=./test-infra/jenkins/bootstrap.py
W1015 21:11:27.769] 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/azure-ssh/azure-ssh-pub', '--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.36.5/aks-engine-v0.36.5-linux-amd64.tar.gz', '--timeout=420m')
W1015 21:11:27.920] 2019/10/15 21:11:27 main.go:332: Limiting testing to 7h0m0s
W1015 21:11:27.921] 2019/10/15 21:11:27 azure.go:232: Reading credentials file /etc/azure-cred/credentials
W1015 21:11:27.922] 2019/10/15 21:11:27 process.go:153: Running: make -C /go/src/k8s.io/kubernetes bazel-release
W1015 21:11:28.001] Extracting Bazel installation...
I1015 21:11:28.102] make: Entering directory '/go/src/k8s.io/kubernetes'
W1015 21:11:36.953] Starting local Bazel server and connecting to it...
W1015 21:11:38.617] Loading: 
W1015 21:11:38.620] Loading: 0 packages loaded
W1015 21:11:39.623] Loading: 0 packages loaded
W1015 21:11:41.215] Loading: 0 packages loaded
W1015 21:11:42.624] Loading: 0 packages loaded
W1015 21:11:44.567] Loading: 0 packages loaded
W1015 21:11:45.624] Loading: 0 packages loaded
W1015 21:11:45.625]     currently loading: build/release-tars
W1015 21:11:47.832] Loading: 0 packages loaded
W1015 21:11:47.832]     currently loading: build/release-tars
W1015 21:11:48.202] Analyzing: target //build/release-tars:release-tars (1 packages loaded, 0 targets configured)
W1015 21:11:49.661] Analyzing: target //build/release-tars:release-tars (154 packages loaded, 946 targets configured)
W1015 21:11:51.343] Analyzing: target //build/release-tars:release-tars (842 packages loaded, 3304 targets configured)
W1015 21:11:53.271] Analyzing: target //build/release-tars:release-tars (1637 packages loaded, 9779 targets configured)
W1015 21:11:55.491] Analyzing: target //build/release-tars:release-tars (2596 packages loaded, 18898 targets configured)
W1015 21:11:58.253] Analyzing: target //build/release-tars:release-tars (3043 packages loaded, 27225 targets configured)
W1015 21:12:01.221] Analyzing: target //build/release-tars:release-tars (3080 packages loaded, 29803 targets configured)
W1015 21:12:05.046] Analyzing: target //build/release-tars:release-tars (3087 packages loaded, 34112 targets configured)
W1015 21:12:23.673] INFO: Analysed target //build/release-tars:release-tars (3087 packages loaded, 42371 targets configured).
W1015 21:12:23.676] Building: checking cached actions
W1015 21:12:23.677] INFO: Found 1 target...
W1015 21:12:24.755] [0 / 20] [-----] BazelWorkspaceStatusAction stable-status.txt ... (3 actions, 0 running)
W1015 21:12:24.755] [0 / 20] [-----] BazelWorkspaceStatusAction stable-status.txt ... (5 actions, 0 running)
W1015 21:12:31.704] [111 / 5,320] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 0s linux-sandbox ... (7 actions, 6 running)
W1015 21:12:39.890] [147 / 5,320] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 9s linux-sandbox ... (8 actions running)
W1015 21:12:49.438] [258 / 5,320] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 18s linux-sandbox ... (7 actions running)
W1015 21:13:00.247] [503 / 5,320] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 29s linux-sandbox ... (8 actions, 7 running)
W1015 21:13:12.900] [572 / 5,320] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 42s linux-sandbox ... (8 actions, 7 running)
W1015 21:13:28.273] [684 / 5,320] GoAsm vendor/gonum.org/v1/gonum/internal/asm/c128/linux_amd64_pure_stripped/go_default_library%/dscalinc_amd64.o; 1s linux-sandbox ... (8 actions running)
W1015 21:13:50.187] [874 / 5,320] 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; 7s linux-sandbox ... (8 actions, 7 running)
W1015 21:14:10.056] [1,003 / 5,320] GoCompile vendor/github.com/aws/aws-sdk-go/service/ec2/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/aws/aws-sdk-go/service/ec2.a; 7s linux-sandbox ... (8 actions, 7 running)
W1015 21:14:32.935] [1,226 / 5,320] GoCompile vendor/github.com/Azure/go-autorest/autorest/azure/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/Azure/go-autorest/autorest/azure.a; 4s linux-sandbox ... (8 actions, 7 running)
W1015 21:14:59.447] [1,456 / 5,320] GoCompile staging/src/k8s.io/cri-api/pkg/apis/runtime/v1alpha2/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/cri-api/pkg/apis/runtime/v1alpha2.a; 4s linux-sandbox ... (8 actions, 7 running)
W1015 21:15:30.842] [1,876 / 5,320] GoCompile vendor/github.com/vmware/govmomi/vim25/methods/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/methods.a; 5s linux-sandbox ... (7 actions, 6 running)
W1015 21:16:05.713] [2,208 / 5,320] GoLink vendor/github.com/onsi/ginkgo/ginkgo/linux_amd64_stripped/ginkgo; 2s linux-sandbox ... (8 actions, 7 running)
W1015 21:16:45.808] [2,649 / 5,320] GoCompile vendor/github.com/Azure/azure-sdk-for-go/services/network/mgmt/2019-06-01/network/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/Azure/azure-sdk-for-go/services/network/mgmt/2019-06-01/network.a; 15s linux-sandbox ... (8 actions, 7 running)
W1015 21:17:40.055] [2,813 / 5,320]  <rule context for //staging/src/k8s.io/sample-apiserver/pkg/generated/openapi:zz_generated.openapi>; 22s linux-sandbox ... (8 actions, 7 running)
W1015 21:18:36.142] [2,973 / 5,320] PackageTar build/release-tars/kubernetes-src.tar.gz; 53s linux-sandbox ... (8 actions running)
W1015 21:19:37.957] [3,307 / 5,320] GoCompile pkg/apis/autoscaling/v1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/pkg/apis/autoscaling/v1.a; 2s linux-sandbox ... (8 actions, 7 running)
W1015 21:20:50.519] [3,748 / 5,320] GoCompile staging/src/k8s.io/client-go/informers/autoscaling/v1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/informers/autoscaling/v1.a; 1s linux-sandbox ... (8 actions, 7 running)
W1015 21:22:13.342] [4,040 / 5,320] GoLink cmd/kube-proxy/linux_amd64_pure_stripped/kube-proxy; 27s linux-sandbox ... (8 actions, 7 running)
W1015 21:23:48.742] [4,433 / 5,320] GoCompile staging/src/k8s.io/client-go/kubernetes/typed/core/v1/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/core/v1.a; 2s linux-sandbox ... (8 actions, 7 running)
W1015 21:25:38.281] [4,993 / 5,320] GoLink cmd/gendocs/gendocs; 13s linux-sandbox ... (8 actions running)
W1015 21:27:46.138] [5,306 / 5,320] GoLink cmd/kubelet/kubelet; 43s linux-sandbox ... (6 actions running)
W1015 21:30:05.509] Target //build/release-tars:release-tars up-to-date:
W1015 21:30:05.558]   bazel-bin/build/release-tars/kubernetes-client-linux-amd64.tar.gz
W1015 21:30:05.558]   bazel-bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz
W1015 21:30:05.558]   bazel-bin/build/release-tars/kubernetes-server-linux-amd64.tar.gz
W1015 21:30:05.558]   bazel-bin/build/release-tars/kubernetes-manifests.tar.gz
W1015 21:30:05.559]   bazel-bin/build/release-tars/kubernetes-test-portable.tar.gz
W1015 21:30:05.559]   bazel-bin/build/release-tars/kubernetes-test-linux-amd64.tar.gz
W1015 21:30:05.559]   bazel-bin/build/release-tars/kubernetes.tar.gz
W1015 21:30:05.559]   bazel-bin/build/release-tars/kubernetes-src.tar.gz
W1015 21:30:05.660] INFO: Elapsed time: 1117.554s, Critical Path: 302.03s
W1015 21:30:05.660] INFO: 5229 processes: 5229 linux-sandbox.
W1015 21:30:05.665] INFO: Build completed successfully, 5320 total actions
W1015 21:30:05.667] INFO: Build completed successfully, 5320 total actions
W1015 21:30:05.673] 2019/10/15 21:30:05 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes bazel-release' finished in 18m37.751511933s
W1015 21:30:05.674] 2019/10/15 21:30:05 util.go:277: Flushing memory.
I1015 21:30:05.774] make: Leaving directory '/go/src/k8s.io/kubernetes'
W1015 21:30:39.279] 2019/10/15 21:30:39 azure.go:906: Deleting resource group: kubetest-5a34237c-ef90-11e9-9f59-02424becdd1f.
W1015 21:30:39.755] 2019/10/15 21:30:39 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1015 21:30:39.756] 2019/10/15 21:30:39 azure.go:673: Attempting Docker login with azure cred.
W1015 21:30:41.236] 2019/10/15 21:30:41 azure.go:682: Docker login success.
W1015 21:30:41.236] 2019/10/15 21:30:41 azure.go:697: Building ccm.
W1015 21:30:41.236] 2019/10/15 21:30:41 azure.go:699: projectPath /go/src/k8s.io/cloud-provider-azure
W1015 21:30:41.236] 2019/10/15 21:30:41 process.go:153: Running: docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184214917721362432-08c03d9b .
I1015 21:30:43.343] Sending build context to Docker daemon  67.18MB

I1015 21:30:43.383] Step 1/7 : FROM golang:1.12.9-stretch AS build
I1015 21:30:44.280] 1.12.9-stretch: Pulling from library/golang
I1015 21:30:44.608] 092586df9206: Pulling fs layer
I1015 21:30:44.608] ef599477fae0: Pulling fs layer
I1015 21:30:44.608] 4530c6472b5d: Pulling fs layer
I1015 21:30:44.609] d34d61487075: Pulling fs layer
I1015 21:30:44.609] 89c6ec31b9e9: Pulling fs layer
I1015 21:30:44.609] e37857ebcafa: Pulling fs layer
I1015 21:30:44.609] b0e29f6c7f0a: Pulling fs layer
I1015 21:30:44.610] d34d61487075: Waiting
I1015 21:30:44.610] b0e29f6c7f0a: Waiting
I1015 21:30:44.610] e37857ebcafa: Waiting
I1015 21:30:45.054] 4530c6472b5d: Verifying Checksum
I1015 21:30:45.054] 4530c6472b5d: Download complete
I1015 21:30:45.144] ef599477fae0: Verifying Checksum
I1015 21:30:45.144] ef599477fae0: Download complete
I1015 21:30:45.358] 092586df9206: Verifying Checksum
I1015 21:30:45.358] 092586df9206: Download complete
I1015 21:30:46.074] d34d61487075: Verifying Checksum
I1015 21:30:46.075] d34d61487075: Download complete
I1015 21:30:46.112] 89c6ec31b9e9: Verifying Checksum
I1015 21:30:46.112] 89c6ec31b9e9: Download complete
I1015 21:30:47.097] e37857ebcafa: Verifying Checksum
I1015 21:30:47.098] e37857ebcafa: Download complete
I1015 21:30:48.519] 092586df9206: Pull complete
I1015 21:30:49.311] ef599477fae0: Pull complete
I1015 21:30:49.643] 4530c6472b5d: Pull complete
I1015 21:30:53.274] d34d61487075: Pull complete
I1015 21:30:56.724] 89c6ec31b9e9: Pull complete
I1015 21:31:04.139] e37857ebcafa: Pull complete
I1015 21:31:04.292] b0e29f6c7f0a: Pull complete
I1015 21:31:04.318] Digest: sha256:76b52857546f070cc3ac499accb27b8c411b10ff6d45c0b1da2a8aab7b61fe29
I1015 21:31:04.337] Status: Downloaded newer image for golang:1.12.9-stretch
I1015 21:31:04.338]  ---> 2c4a601e5da9
I1015 21:31:04.338] Step 2/7 : WORKDIR /go/src/k8s.io/cloud-provider-azure
I1015 21:31:16.282]  ---> Running in fe29e934a44f
I1015 21:31:17.443] Removing intermediate container fe29e934a44f
I1015 21:31:17.444]  ---> 12267f6fac62
I1015 21:31:17.444] Step 3/7 : COPY . .
I1015 21:31:23.205]  ---> 0e1c86e8097b
I1015 21:31:23.205] Step 4/7 : RUN make
I1015 21:31:23.396]  ---> Running in b47f82a7ad77
I1015 21:31:24.279] hack/pkg-config.sh > .pkg_config
I1015 21:31:24.306] go build -o bin/azure-cloud-controller-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-10-gbdcbdd2f0 -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=bdcbdd2f0a8f0773b4c52ac0a09d52b5fe6cfcbd -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-15T21:31:24Z' ./cmd/cloud-controller-manager
I1015 21:32:06.420] go build -o bin/azure-cloud-node-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-10-gbdcbdd2f0 -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=bdcbdd2f0a8f0773b4c52ac0a09d52b5fe6cfcbd -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-15T21:31:24Z' ./cmd/cloud-node-manager
I1015 21:32:30.306] Removing intermediate container b47f82a7ad77
I1015 21:32:30.306]  ---> b71b556cec98
I1015 21:32:30.306] Step 5/7 : FROM k8s.gcr.io/debian-base:v1.0.0
I1015 21:32:30.620] v1.0.0: Pulling from debian-base
I1015 21:32:30.782] 39fafc05754f: Pulling fs layer
I1015 21:32:31.168] 39fafc05754f: Verifying Checksum
I1015 21:32:31.168] 39fafc05754f: Download complete
I1015 21:32:33.621] 39fafc05754f: Pull complete
I1015 21:32:33.645] Digest: sha256:3801f944c765dc1b54900826ca67b1380bb8c73b9caf4a2a27ce613b3ba3e742
I1015 21:32:33.664] Status: Downloaded newer image for k8s.gcr.io/debian-base:v1.0.0
I1015 21:32:33.664]  ---> 204e96332c91
I1015 21:32:33.664] Step 6/7 : COPY --from=build /go/src/k8s.io/cloud-provider-azure/bin/azure-cloud-controller-manager /usr/local/bin
I1015 21:32:37.034]  ---> b5c42ca5fb48
I1015 21:32:37.034] Step 7/7 : RUN ln -s /usr/local/bin/azure-cloud-controller-manager /usr/local/bin/cloud-controller-manager
I1015 21:32:37.180]  ---> Running in 3e4253717dad
I1015 21:32:39.058] Removing intermediate container 3e4253717dad
I1015 21:32:39.058]  ---> 6ec9372f837a
I1015 21:32:39.159] Successfully built 6ec9372f837a
I1015 21:32:39.285] Successfully tagged k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184214917721362432-08c03d9b
W1015 21:32:39.386] 2019/10/15 21:32:39 process.go:155: Step 'docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184214917721362432-08c03d9b .' finished in 1m58.053491781s
W1015 21:32:39.386] 2019/10/15 21:32:39 process.go:153: Running: docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184214917721362432-08c03d9b
W1015 21:32:43.466] 2019/10/15 21:32:43 process.go:155: Step 'docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184214917721362432-08c03d9b' finished in 4.17709312s
W1015 21:32:43.467] 2019/10/15 21:32:43 azure.go:686: Docker logout.
W1015 21:32:43.530] 2019/10/15 21:32:43 azure.go:716: Custom cloud controller manager URL: k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184214917721362432-08c03d9b .
W1015 21:32:43.530] 2019/10/15 21:32:43 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1015 21:32:43.530] 2019/10/15 21:32:43 azure.go:673: Attempting Docker login with azure cred.
W1015 21:32:44.661] 2019/10/15 21:32:44 azure.go:682: Docker login success.
W1015 21:32:44.661] 2019/10/15 21:32:44 azure.go:726: Building hyperkube.
W1015 21:32:44.661] 2019/10/15 21:32:44 process.go:153: Running: make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube
W1015 21:32:46.617] 
W1015 21:32:46.617] Detected go version: go version go1.12.1 linux/amd64.
W1015 21:32:46.617] Kubernetes requires go1.12.4 or greater.
W1015 21:32:46.617] Please install go1.12.4 or later.
W1015 21:32:46.617] 
W1015 21:32:46.621] !!! [1015 21:32:46] Call tree:
W1015 21:32:46.623] !!! [1015 21:32:46]  1: hack/run-in-gopath.sh:30 kube::golang::setup_env(...)
W1015 21:32:46.668] 
W1015 21:32:46.668] Detected go version: go version go1.12.1 linux/amd64.
W1015 21:32:46.668] Kubernetes requires go1.12.4 or greater.
W1015 21:32:46.668] Please install go1.12.4 or later.
W1015 21:32:46.668] 
W1015 21:32:46.671] !!! [1015 21:32:46] Call tree:
W1015 21:32:46.672] !!! [1015 21:32:46]  1: /go/src/k8s.io/kubernetes/hack/lib/golang.sh:772 kube::golang::setup_env(...)
W1015 21:32:46.674] !!! [1015 21:32:46]  2: hack/make-rules/build.sh:27 kube::golang::build_binaries(...)
W1015 21:32:46.678] !!! [1015 21:32:46] Call tree:
W1015 21:32:46.679] !!! [1015 21:32:46]  1: hack/make-rules/build.sh:27 kube::golang::build_binaries(...)
W1015 21:32:46.680] make[1]: *** [_output/bin/deepcopy-gen] Error 1
W1015 21:32:46.680] make: *** [generated_files] Error 2
W1015 21:32:46.680] 2019/10/15 21:32:46 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube' finished in 2.019090177s
W1015 21:32:46.680] 2019/10/15 21:32:46 process.go:153: Running: /workspace/_artifacts
W1015 21:32:46.681] 2019/10/15 21:32:46 process.go:155: Step '/workspace/_artifacts' finished in 700.505µs
W1015 21:32:46.681] 2019/10/15 21:32:46 azure.go:906: Deleting resource group: kubetest-5a34237c-ef90-11e9-9f59-02424becdd1f.
W1015 21:32:46.709] 2019/10/15 21:32:46 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml.
W1015 21:32:46.710] 2019/10/15 21:32:46 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
W1015 21:32:47.386] 2019/10/15 21:32:47 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 676.741387ms
W1015 21:32:47.386] 2019/10/15 21:32:47 main.go:319: Something went wrong: starting e2e cluster: error building hyperkube error during make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube: exit status 2
W1015 21:32:47.388] Traceback (most recent call last):
W1015 21:32:47.389]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module>
W1015 21:32:47.389]     main(parse_args())
W1015 21:32:47.389]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main
W1015 21:32:47.389]     mode.start(runner_args)
W1015 21:32:47.390]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start
W1015 21:32:47.390]     check_env(env, self.command, *args)
W1015 21:32:47.390]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env
W1015 21:32:47.390]     subprocess.check_call(cmd, env=env)
W1015 21:32:47.390]   File "/usr/lib/python2.7/subprocess.py", line 186, in check_call
W1015 21:32:47.390]     raise CalledProcessError(retcode, cmd)
W1015 21:32:47.391] 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/azure-ssh/azure-ssh-pub', '--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.36.5/aks-engine-v0.36.5-linux-amd64.tar.gz', '--timeout=420m')' returned non-zero exit status 1
E1015 21:32:47.396] Command failed
I1015 21:32:47.396] process 690 exited with code 1 after 21.3m
E1015 21:32:47.396] FAIL: chewong-e2e-ccm
I1015 21:32:47.398] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1015 21:32:48.209] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1015 21:32:48.240] process 14255 exited with code 0 after 0.0m
I1015 21:32:48.240] Call:  gcloud config get-value account
I1015 21:32:48.495] process 14267 exited with code 0 after 0.0m
I1015 21:32:48.495] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1015 21:32:48.495] Upload result and artifacts...
I1015 21:32:48.495] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432
I1015 21:32:48.495] Call:  gsutil ls gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432/artifacts
W1015 21:32:49.689] CommandException: One or more URLs matched no objects.
E1015 21:32:49.768] Command failed
I1015 21:32:49.768] process 14279 exited with code 1 after 0.0m
W1015 21:32:49.768] Remote dir gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432/artifacts not exist yet
I1015 21:32:49.768] 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/1184214917721362432/artifacts
I1015 21:32:51.533] process 14421 exited with code 0 after 0.0m
I1015 21:32:51.534] Call:  git rev-parse HEAD
I1015 21:32:51.537] process 14945 exited with code 0 after 0.0m
I1015 21:32:51.537] Call:  git rev-parse HEAD
I1015 21:32:51.541] process 14946 exited with code 0 after 0.0m
I1015 21:32:51.542] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1015 21:32:52.516] process 14947 exited with code 0 after 0.0m
I1015 21:32:52.517] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json#1571098120041740'
I1015 21:32:53.766] process 15089 exited with code 0 after 0.0m
I1015 21:32:53.767] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571098120041740 cp /tmp/gsutil_bZW5eF gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1015 21:32:55.253] process 15233 exited with code 0 after 0.0m
I1015 21:32:55.254] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1015 21:32:56.181] process 15411 exited with code 0 after 0.0m
I1015 21:32:56.181] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json#1571098122336660'
I1015 21:32:57.400] process 15553 exited with code 0 after 0.0m
I1015 21:32:57.401] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571098122336660 cp /tmp/gsutil_eBkkmW gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1015 21:32:58.863] process 15697 exited with code 0 after 0.0m
I1015 21:32:58.863] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_2AULy5 gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184214917721362432/finished.json
I1015 21:33:00.146] process 15875 exited with code 0 after 0.0m
I1015 21:33:00.147] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_Nstj8k gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/latest-build.txt
I1015 21:33:01.478] process 16053 exited with code 0 after 0.0m
I1015 21:33:01.479] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_i9UGEa gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/latest-build.txt
I1015 21:33:02.805] process 16231 exited with code 0 after 0.0m