W1126 18:52:58.256] **************************************************************************
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
**************************************************************************
I1126 18:52:58.257] Args: --job=chewong-in-tree-azure-disk-e2e --service-account=/etc/service-account/service-account.json --upload=gs://kubernetes-jenkins/logs --job=chewong-in-tree-azure-disk-e2e --root=/go/src --service-account=/etc/service-account/service-account.json --repo=k8s.io/kubernetes=master:1c5b6cb66e6ae85177e76d4fddf7d99473ab2aed,85621:dd76fdfce5554cc15ee7ed999bea1cffb0436d0a --upload=gs://kubernetes-upstream/pr-logs --timeout=460 --scenario=kubernetes_e2e -- --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=host-go --provider=azure --ginkgo-parallel=10 --acsengine-agentpoolcount=2 --acsengine-admin-username=azureuser '--acsengine-creds=$AZURE_CREDENTIALS' --acsengine-orchestratorRelease=1.16 --acsengine-mastervmsize=Standard_DS2_v2 --acsengine-agentvmsize=Standard_D4s_v3 --acsengine-hyperkube=True --acsengine-location=westus2 '--acsengine-public-key=$AZURE_SSH_PUBLIC_KEY_FILE' --acsengine-template-url=https://raw.githubusercontent.com/Azure/aks-engine/master/examples/kubernetes-vmss/kubernetes.json --acsengine-download-url=https://aka.ms/aks-engine/aks-engine-k8s-e2e.tar.gz '--test_args=--ginkgo.focus=azure-disk --ginkgo.skip=\[Slow\]|\[Serial\]|\[Disruptive\]|\[Flaky\]|\[Feature:.+\]' --timeout=420m
I1126 18:52:58.257] Bootstrap chewong-in-tree-azure-disk-e2e...
I1126 18:52:58.260] Builder: e9cfefd0-107d-11ea-918b-16773c0c7aed
I1126 18:52:58.260] Image: gcr.io/k8s-testimages/kubekins-e2e:v20191124-4beb966-master
I1126 18:52:58.261] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120
I1126 18:52:58.261] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1126 18:52:58.785] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1126 18:52:58.815] process 213 exited with code 0 after 0.0m
I1126 18:52:58.816] Call:  gcloud config get-value account
I1126 18:52:59.052] process 226 exited with code 0 after 0.0m
I1126 18:52:59.052] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1126 18:52:59.052] Root: /go/src
I1126 18:52:59.052] cd to /go/src
I1126 18:52:59.053] Checkout: /go/src/k8s.io/kubernetes master:1c5b6cb66e6ae85177e76d4fddf7d99473ab2aed,85621:dd76fdfce5554cc15ee7ed999bea1cffb0436d0a to /go/src/k8s.io/kubernetes
I1126 18:52:59.053] Call:  git init k8s.io/kubernetes
I1126 18:52:59.057] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/
I1126 18:52:59.057] process 239 exited with code 0 after 0.0m
I1126 18:52:59.057] Call:  git config --local user.name 'K8S Bootstrap'
I1126 18:52:59.059] process 240 exited with code 0 after 0.0m
I1126 18:52:59.060] Call:  git config --local user.email k8s_bootstrap@localhost
I1126 18:52:59.062] process 241 exited with code 0 after 0.0m
I1126 18:52:59.062] Call:  git fetch --quiet --tags https://github.com/kubernetes/kubernetes master +refs/pull/85621/head:refs/pr/85621
I1126 18:53:58.299] process 242 exited with code 0 after 1.0m
I1126 18:53:58.299] Call:  git checkout -B test 1c5b6cb66e6ae85177e76d4fddf7d99473ab2aed
W1126 18:54:00.523] Switched to a new branch 'test'
I1126 18:54:00.532] process 253 exited with code 0 after 0.0m
I1126 18:54:00.532] Call:  git show -s --format=format:%ct HEAD
I1126 18:54:00.557] process 254 exited with code 0 after 0.0m
I1126 18:54:00.558] Call:  git merge --no-ff -m 'Merge +refs/pull/85621/head:refs/pr/85621' dd76fdfce5554cc15ee7ed999bea1cffb0436d0a
I1126 18:54:01.323] Merge made by the 'recursive' strategy.
I1126 18:54:01.326]  test/e2e/storage/drivers/in_tree.go | 46 ++++++++++++++++++-------------------
I1126 18:54:01.326]  test/e2e/storage/in_tree_volumes.go |  2 +-
I1126 18:54:01.326]  2 files changed, 24 insertions(+), 24 deletions(-)
I1126 18:54:01.327] process 255 exited with code 0 after 0.0m
I1126 18:54:01.327] Configure environment...
I1126 18:54:01.327] Call:  git show -s --format=format:%ct HEAD
I1126 18:54:01.331] process 297 exited with code 0 after 0.0m
I1126 18:54:01.331] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1126 18:54:01.978] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1126 18:54:02.101] process 298 exited with code 0 after 0.0m
I1126 18:54:02.101] Call:  gcloud config get-value account
I1126 18:54:02.340] process 311 exited with code 0 after 0.0m
I1126 18:54:02.340] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1126 18:54:02.340] 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
'
I1126 18:54:02.566] process 324 exited with code 0 after 0.0m
I1126 18:54:02.566] Start 1199400605160837120 at v1.18.0-alpha.0.1190+cff90159704e47...
I1126 18:54:02.568] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_y3A9sV gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120/started.json
I1126 18:54:03.931] process 357 exited with code 0 after 0.0m
I1126 18:54:03.931] Call:  gsutil -q -h Content-Type:text/plain -h 'x-goog-meta-link: gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120' cp /tmp/gsutil_PnwVSA gs://kubernetes-upstream/pr-logs/directory/chewong-in-tree-azure-disk-e2e/1199400605160837120.txt
I1126 18:54:05.094] process 538 exited with code 0 after 0.0m
I1126 18:54:05.095] Call:  /workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=host-go --provider=azure --ginkgo-parallel=10 --acsengine-agentpoolcount=2 --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-location=westus2 --acsengine-public-key=/etc/azure-ssh/azure-ssh-pub --acsengine-template-url=https://raw.githubusercontent.com/Azure/aks-engine/master/examples/kubernetes-vmss/kubernetes.json --acsengine-download-url=https://aka.ms/aks-engine/aks-engine-k8s-e2e.tar.gz '--test_args=--ginkgo.focus=azure-disk --ginkgo.skip=\[Slow\]|\[Serial\]|\[Disruptive\]|\[Flaky\]|\[Feature:.+\]' --timeout=420m
W1126 18:54:05.140] starts with local mode
W1126 18:54:05.140] Environment:
W1126 18:54:05.140] ARTIFACTS=/workspace/_artifacts
W1126 18:54:05.141] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa
W1126 18:54:05.141] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub
W1126 18:54:05.141] AZURE_CREDENTIALS=/etc/azure-cred/credentials
W1126 18:54:05.141] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub
W1126 18:54:05.141] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer
W1126 18:54:05.141] BAZEL_REMOTE_CACHE_ENABLED=false
W1126 18:54:05.142] BAZEL_VERSION=0.23.2
W1126 18:54:05.142] BOOTSTRAP_MIGRATION=yes
W1126 18:54:05.142] BUILD_ID=1199400605160837120
W1126 18:54:05.142] BUILD_NUMBER=1199400605160837120
W1126 18:54:05.142] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true
W1126 18:54:05.142] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud
W1126 18:54:05.142] CLOUDSDK_CORE_DISABLE_PROMPTS=1
W1126 18:54:05.143] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false
W1126 18:54:05.143] CLOUD_CONFIG=random
W1126 18:54:05.143] DECK_PORT=tcp://10.0.160.83:80
W1126 18:54:05.143] DECK_PORT_80_TCP=tcp://10.0.160.83:80
W1126 18:54:05.143] DECK_PORT_80_TCP_ADDR=10.0.160.83
W1126 18:54:05.143] DECK_PORT_80_TCP_PORT=80
W1126 18:54:05.143] DECK_PORT_80_TCP_PROTO=tcp
W1126 18:54:05.143] DECK_SERVICE_HOST=10.0.160.83
W1126 18:54:05.143] DECK_SERVICE_PORT=80
W1126 18:54:05.144] DOCKER_IN_DOCKER_ENABLED=true
W1126 18:54:05.144] DOCKER_IN_DOCKER_IPV6_ENABLED=false
W1126 18:54:05.144] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120/artifacts
W1126 18:54:05.144] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json
W1126 18:54:05.144] GOPATH=/go
W1126 18:54:05.144] GO_TARBALL=go1.12.12.linux-amd64.tar.gz
W1126 18:54:05.144] HOME=/workspace
W1126 18:54:05.145] HOOK_PORT=tcp://10.0.144.133:8888
W1126 18:54:05.145] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888
W1126 18:54:05.145] HOOK_PORT_8888_TCP_ADDR=10.0.144.133
W1126 18:54:05.145] HOOK_PORT_8888_TCP_PORT=8888
W1126 18:54:05.145] HOOK_PORT_8888_TCP_PROTO=tcp
W1126 18:54:05.145] HOOK_SERVICE_HOST=10.0.144.133
W1126 18:54:05.145] HOOK_SERVICE_PORT=8888
W1126 18:54:05.146] HOSTNAME=e9cfefd0-107d-11ea-918b-16773c0c7aed
W1126 18:54:05.146] IMAGE=gcr.io/k8s-testimages/kubekins-e2e:v20191124-4beb966-master
W1126 18:54:05.146] INSTANCE_PREFIX=bootstrap-e2e
W1126 18:54:05.146] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine
W1126 18:54:05.146] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub
W1126 18:54:05.146] JOB_NAME=chewong-in-tree-azure-disk-e2e
W1126 18:54:05.147] JOB_SPEC={"type":"presubmit","job":"chewong-in-tree-azure-disk-e2e","buildid":"1199400605160837120","prowjobid":"e9cfefd0-107d-11ea-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"036cf78b513df081015052cb6863a02c789a2c89","base_link":"https://github.com/Azure/kubernetes/commit/036cf78b513df081015052cb6863a02c789a2c89","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"}]}}
W1126 18:54:05.147] JOB_TYPE=presubmit
W1126 18:54:05.147] KUBERNETES_CONFORMANCE_PROVIDER=azure
W1126 18:54:05.147] KUBERNETES_PORT=tcp://10.0.0.1:443
W1126 18:54:05.147] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443
W1126 18:54:05.148] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1
W1126 18:54:05.148] KUBERNETES_PORT_443_TCP_PORT=443
W1126 18:54:05.148] KUBERNETES_PORT_443_TCP_PROTO=tcp
W1126 18:54:05.148] KUBERNETES_SERVICE_HOST=10.0.0.1
W1126 18:54:05.148] KUBERNETES_SERVICE_PORT=443
W1126 18:54:05.148] KUBERNETES_SERVICE_PORT_HTTPS=443
W1126 18:54:05.149] KUBETEST_IN_DOCKER=true
W1126 18:54:05.149] KUBETEST_MANUAL_DUMP=y
W1126 18:54:05.149] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e
W1126 18:54:05.149] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e
W1126 18:54:05.149] KUBE_SSH_KEY_PATH=/etc/ssh-key-secret/ssh-private
W1126 18:54:05.149] KUBE_SSH_PUBLIC_KEY_PATH=/etc/ssh-key-secret/ssh-public
W1126 18:54:05.149] KUBE_SSH_USER=azureuser
W1126 18:54:05.150] KUBE_VERBOSE=0
W1126 18:54:05.150] NODE_NAME=e9cfefd0-107d-11ea-918b-16773c0c7aed
W1126 18:54:05.150] 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
W1126 18:54:05.150] PROW_JOB_ID=e9cfefd0-107d-11ea-918b-16773c0c7aed
W1126 18:54:05.150] PULL_BASE_REF=master
W1126 18:54:05.150] PULL_BASE_SHA=036cf78b513df081015052cb6863a02c789a2c89
W1126 18:54:05.150] PULL_NUMBER=113
W1126 18:54:05.151] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822
W1126 18:54:05.151] PULL_REFS=master:036cf78b513df081015052cb6863a02c789a2c89,113:879465972041635fd7bc8269da49153b67e63822
W1126 18:54:05.151] PWD=/workspace
W1126 18:54:05.151] REGISTRY=k8sprowinternal.azurecr.io
W1126 18:54:05.151] REPO_NAME=kubernetes
W1126 18:54:05.151] REPO_OWNER=Azure
W1126 18:54:05.151] SHLVL=2
W1126 18:54:05.151] SOURCE_DATE_EPOCH=1574729000
W1126 18:54:05.152] TERM=xterm
W1126 18:54:05.152] TIDE_PORT=tcp://10.0.180.53:80
W1126 18:54:05.152] TIDE_PORT_80_TCP=tcp://10.0.180.53:80
W1126 18:54:05.152] TIDE_PORT_80_TCP_ADDR=10.0.180.53
W1126 18:54:05.152] TIDE_PORT_80_TCP_PORT=80
W1126 18:54:05.152] TIDE_PORT_80_TCP_PROTO=tcp
W1126 18:54:05.152] TIDE_SERVICE_HOST=10.0.180.53
W1126 18:54:05.153] TIDE_SERVICE_PORT=80
W1126 18:54:05.153] WORKSPACE=/workspace
W1126 18:54:05.153] _=./test-infra/jenkins/bootstrap.py
W1126 18:54:05.153] Run: ('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=host-go', '--up', '--down', '--test', '--deployment=acsengine', '--provider=azure', '--cluster=bootstrap-e2e', '--gcp-network=bootstrap-e2e', '--ginkgo-parallel=10', '--acsengine-agentpoolcount=2', '--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-location=westus2', '--acsengine-public-key=/etc/azure-ssh/azure-ssh-pub', '--acsengine-template-url=https://raw.githubusercontent.com/Azure/aks-engine/master/examples/kubernetes-vmss/kubernetes.json', '--acsengine-download-url=https://aka.ms/aks-engine/aks-engine-k8s-e2e.tar.gz', '--test_args=--ginkgo.focus=azure-disk --ginkgo.skip=\\[Slow\\]|\\[Serial\\]|\\[Disruptive\\]|\\[Flaky\\]|\\[Feature:.+\\]', '--timeout=420m')
W1126 18:54:05.161] 2019/11/26 18:54:05 main.go:332: Limiting testing to 7h0m0s
W1126 18:54:05.164] 2019/11/26 18:54:05 azure.go:242: Reading credentials file /etc/azure-cred/credentials
W1126 18:54:05.165] 2019/11/26 18:54:05 process.go:153: Running: make -C /go/src/k8s.io/kubernetes all
I1126 18:54:05.265] make: Entering directory '/go/src/k8s.io/kubernetes'
I1126 18:54:05.265] make[1]: Entering directory '/go/src/k8s.io/kubernetes'
I1126 18:54:13.014] +++ [1126 18:54:13] Building go targets for linux/amd64:
I1126 18:54:13.014]     ./vendor/k8s.io/code-generator/cmd/deepcopy-gen
I1126 18:54:20.021] +++ [1126 18:54:20] Building go targets for linux/amd64:
I1126 18:54:20.021]     ./vendor/k8s.io/code-generator/cmd/defaulter-gen
I1126 18:54:25.712] +++ [1126 18:54:25] Building go targets for linux/amd64:
I1126 18:54:25.712]     ./vendor/k8s.io/code-generator/cmd/conversion-gen
I1126 18:54:35.213] +++ [1126 18:54:35] Building go targets for linux/amd64:
I1126 18:54:35.213]     ./vendor/k8s.io/kube-openapi/cmd/openapi-gen
I1126 18:54:47.227] +++ [1126 18:54:47] Building go targets for linux/amd64:
I1126 18:54:47.227]     ./vendor/github.com/go-bindata/go-bindata/go-bindata
I1126 18:54:48.497] make[1]: Leaving directory '/go/src/k8s.io/kubernetes'
I1126 18:54:48.810] +++ [1126 18:54:48] Building go targets for linux/amd64:
I1126 18:54:48.810]     cmd/kube-proxy
I1126 18:54:48.810]     cmd/kube-apiserver
I1126 18:54:48.810]     cmd/kube-controller-manager
I1126 18:54:48.811]     cmd/kubelet
I1126 18:54:48.811]     cmd/kubeadm
I1126 18:54:48.811]     cmd/kube-scheduler
I1126 18:54:48.811]     vendor/k8s.io/apiextensions-apiserver
I1126 18:54:48.811]     cluster/gce/gci/mounter
I1126 18:54:48.811]     cmd/kubectl
I1126 18:54:48.812]     cmd/gendocs
I1126 18:54:48.812]     cmd/genkubedocs
I1126 18:54:48.812]     cmd/genman
I1126 18:54:48.812]     cmd/genyaml
I1126 18:54:48.812]     cmd/genswaggertypedocs
I1126 18:54:48.813]     cmd/linkcheck
I1126 18:54:48.814]     vendor/github.com/onsi/ginkgo/ginkgo
I1126 18:54:48.814]     test/e2e/e2e.test
I1126 18:54:48.814]     cluster/images/conformance/go-runner
I1126 18:54:48.814]     cmd/kubemark
I1126 18:54:48.814]     vendor/github.com/onsi/ginkgo/ginkgo
I1126 18:54:48.814]     test/e2e_node/e2e_node.test
I1126 18:59:05.781] make: Leaving directory '/go/src/k8s.io/kubernetes'
W1126 18:59:05.882] 2019/11/26 18:59:05 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes all' finished in 5m0.616509843s
W1126 18:59:05.882] 2019/11/26 18:59:05 util.go:265: Flushing memory.
W1126 18:59:25.927] 2019/11/26 18:59:25 azure.go:959: Deleting resource group: kubetest-1e7c5701-107e-11ea-99b0-02423d69ff80.
W1126 18:59:26.283] 2019/11/26 18:59:26 azure.go:694: CWD /go/src/k8s.io/kubernetes
W1126 18:59:26.283] 2019/11/26 18:59:26 azure.go:713: Attempting Docker login with azure cred.
W1126 18:59:27.623] 2019/11/26 18:59:27 azure.go:722: Docker login success.
W1126 18:59:27.623] 2019/11/26 18:59:27 azure.go:763: Building hyperkube.
W1126 18:59:27.624] 2019/11/26 18:59:27 util.go:56: Warning: Couldn't find directory src/k8s.io/kubernetes/cmd/hyperkube under any of GOPATH /go, defaulting to /go/src/k8s.io/kubernetes/cmd/hyperkube
W1126 18:59:27.624] 2019/11/26 18:59:27 azure.go:781: Pushing hyperkube.
W1126 18:59:27.624] 2019/11/26 18:59:27 process.go:153: Running: make -C /go/src/k8s.io/kubernetes/cluster/images/hyperkube push
I1126 18:59:27.725] make: Entering directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
I1126 18:59:27.725] cp -r ./* /tmp/hyperkube6Lffuv
I1126 18:59:27.725] tar -cvzf /tmp/hyperkube6Lffuv/binaries.tgz  -C /go/src/k8s.io/kubernetes/cluster/images/hyperkube/../../../_output/local/bin/linux/amd64 kube-apiserver kube-controller-manager \
I1126 18:59:27.725] 	kube-proxy kube-scheduler kubectl kubelet
I1126 18:59:27.726] kube-apiserver
I1126 18:59:32.951] kube-controller-manager
I1126 18:59:37.876] kube-proxy
I1126 18:59:39.830] kube-scheduler
I1126 18:59:42.055] kubectl
I1126 18:59:44.327] kubelet
I1126 18:59:49.457] chmod a+rx /tmp/hyperkube6Lffuv/hyperkube
I1126 18:59:49.458] cd /tmp/hyperkube6Lffuv && sed -i.back "s|BASEIMAGE|k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1|g" Dockerfile
I1126 18:59:49.462] docker build --pull -t k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1199400605160837120-1e7c480c /tmp/hyperkube6Lffuv
I1126 18:59:50.298] Sending build context to Docker daemon  122.6MB

I1126 18:59:50.322] Step 1/4 : FROM k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1126 18:59:50.745] 0.12.1: Pulling from debian-hyperkube-base-amd64
I1126 18:59:50.746] 346aee5ea5bc: Pulling fs layer
I1126 18:59:50.746] 9c47fde751af: Pulling fs layer
I1126 18:59:50.746] be2693a52daf: Pulling fs layer
I1126 18:59:50.747] 6b69eb11d043: Pulling fs layer
I1126 18:59:50.747] 0abeb1500767: Pulling fs layer
I1126 18:59:50.747] 4062d80041b7: Pulling fs layer
I1126 18:59:50.747] 23b6daf06fc2: Pulling fs layer
I1126 18:59:50.747] 0abeb1500767: Waiting
I1126 18:59:50.747] 23b6daf06fc2: Waiting
I1126 18:59:50.747] 4062d80041b7: Waiting
I1126 18:59:50.748] 6b69eb11d043: Waiting
I1126 18:59:50.900] 9c47fde751af: Verifying Checksum
I1126 18:59:50.900] 9c47fde751af: Download complete
I1126 18:59:51.041] 6b69eb11d043: Download complete
I1126 18:59:51.054] be2693a52daf: Verifying Checksum
I1126 18:59:51.055] be2693a52daf: Download complete
I1126 18:59:51.122] 346aee5ea5bc: Verifying Checksum
I1126 18:59:51.123] 346aee5ea5bc: Download complete
I1126 18:59:51.184] 0abeb1500767: Verifying Checksum
I1126 18:59:51.185] 0abeb1500767: Download complete
I1126 18:59:52.201] 23b6daf06fc2: Verifying Checksum
I1126 18:59:52.201] 23b6daf06fc2: Download complete
I1126 18:59:52.335] 346aee5ea5bc: Pull complete
I1126 18:59:52.484] 9c47fde751af: Pull complete
I1126 18:59:52.707] be2693a52daf: Pull complete
I1126 18:59:52.882] 6b69eb11d043: Pull complete
I1126 18:59:53.042] 0abeb1500767: Pull complete
I1126 18:59:53.608] 4062d80041b7: Verifying Checksum
I1126 18:59:53.608] 4062d80041b7: Download complete
I1126 18:59:59.818] 4062d80041b7: Pull complete
I1126 19:00:00.736] 23b6daf06fc2: Pull complete
I1126 19:00:00.763] Digest: sha256:5d4ea2fb5fbe9a9a9da74f67cf2faefc881968bc39f2ac5d62d9167e575812a1
I1126 19:00:00.793] Status: Downloaded newer image for k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1126 19:00:00.794]  ---> a46476511725
I1126 19:00:00.794] Step 2/4 : ADD binaries.tgz /usr/local/bin
I1126 19:00:27.955]  ---> 8609b32afda2
I1126 19:00:27.955] Step 3/4 : COPY hyperkube /hyperkube
I1126 19:00:29.062]  ---> dfea17bf1740
I1126 19:00:29.063] Step 4/4 : ENTRYPOINT ["/hyperkube"]
I1126 19:00:29.201]  ---> Running in 958316c63db7
I1126 19:00:30.086] Removing intermediate container 958316c63db7
I1126 19:00:30.086]  ---> 98c017833b6a
I1126 19:00:30.101] Successfully built 98c017833b6a
I1126 19:00:30.233] Successfully tagged k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1199400605160837120-1e7c480c
I1126 19:00:30.237] rm -rf "/tmp/hyperkube6Lffuv"
I1126 19:00:30.257] docker push k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1199400605160837120-1e7c480c
I1126 19:00:30.360] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube-amd64]
I1126 19:00:30.372] 9f7b6584c2a2: Preparing
I1126 19:00:30.372] 2020a52f523d: Preparing
I1126 19:00:30.373] 39b3ac6d96e9: Preparing
I1126 19:00:30.373] 7bbae4dddb88: Preparing
I1126 19:00:30.373] a00defcfe869: Preparing
I1126 19:00:30.373] 2ab0ae805c74: Preparing
I1126 19:00:30.373] 43a8fe7d2382: Preparing
I1126 19:00:30.373] 3f6a6f542637: Preparing
I1126 19:00:30.373] 5ba3be777c2d: Preparing
I1126 19:00:30.374] 43a8fe7d2382: Waiting
I1126 19:00:30.374] 3f6a6f542637: Waiting
I1126 19:00:30.374] 5ba3be777c2d: Waiting
I1126 19:00:30.374] 2ab0ae805c74: Waiting
I1126 19:00:30.575] 7bbae4dddb88: Layer already exists
I1126 19:00:30.597] 39b3ac6d96e9: Layer already exists
I1126 19:00:30.618] a00defcfe869: Layer already exists
I1126 19:00:30.667] 2ab0ae805c74: Layer already exists
I1126 19:00:30.698] 43a8fe7d2382: Layer already exists
I1126 19:00:30.740] 3f6a6f542637: Layer already exists
I1126 19:00:30.763] 5ba3be777c2d: Layer already exists
I1126 19:00:30.765] 9f7b6584c2a2: Pushed
I1126 19:00:55.280] 2020a52f523d: Pushed
I1126 19:00:56.083] azure-e2e-1199400605160837120-1e7c480c: digest: sha256:5496668e38c2b8a3c7d61079ccc2af64f88ba29f3351179f936d30c45cabf755 size: 2206
I1126 19:00:56.103] docker rmi k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1199400605160837120-1e7c480c 2>/dev/null || true
I1126 19:00:56.147] docker tag k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1199400605160837120-1e7c480c k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1199400605160837120-1e7c480c
I1126 19:00:56.211] docker push k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1199400605160837120-1e7c480c
I1126 19:00:56.273] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube]
I1126 19:00:56.292] 9f7b6584c2a2: Preparing
I1126 19:00:56.292] 2020a52f523d: Preparing
I1126 19:00:56.292] 39b3ac6d96e9: Preparing
I1126 19:00:56.292] 7bbae4dddb88: Preparing
I1126 19:00:56.293] a00defcfe869: Preparing
I1126 19:00:56.293] 2ab0ae805c74: Preparing
I1126 19:00:56.293] 43a8fe7d2382: Preparing
I1126 19:00:56.293] 3f6a6f542637: Preparing
I1126 19:00:56.293] 5ba3be777c2d: Preparing
I1126 19:00:56.293] 43a8fe7d2382: Waiting
I1126 19:00:56.293] 2ab0ae805c74: Waiting
I1126 19:00:56.293] 3f6a6f542637: Waiting
I1126 19:00:56.398] 7bbae4dddb88: Layer already exists
I1126 19:00:56.421] 39b3ac6d96e9: Layer already exists
I1126 19:00:56.442] a00defcfe869: Layer already exists
I1126 19:00:56.473] 2ab0ae805c74: Layer already exists
I1126 19:00:56.499] 43a8fe7d2382: Layer already exists
I1126 19:00:56.499] 9f7b6584c2a2: Mounted from hyperkube-amd64
I1126 19:00:56.521] 3f6a6f542637: Layer already exists
I1126 19:00:56.551] 2020a52f523d: Mounted from hyperkube-amd64
I1126 19:00:56.567] 5ba3be777c2d: Layer already exists
I1126 19:00:57.178] azure-e2e-1199400605160837120-1e7c480c: digest: sha256:5496668e38c2b8a3c7d61079ccc2af64f88ba29f3351179f936d30c45cabf755 size: 2206
I1126 19:00:57.193] make: Leaving directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
W1126 19:00:57.293] 2019/11/26 19:00:57 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes/cluster/images/hyperkube push' finished in 1m29.56913022s
W1126 19:00:57.294] 2019/11/26 19:00:57 azure.go:787: Custom hyperkube URL: k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1199400605160837120-1e7c480c .
W1126 19:00:57.294] 2019/11/26 19:00:57 azure.go:830: downloading /workspace/aks406302063/kubernetes.json from https://raw.githubusercontent.com/Azure/aks-engine/master/examples/kubernetes-vmss/kubernetes.json.
W1126 19:00:57.294] 2019/11/26 19:00:57 util.go:42: curl https://raw.githubusercontent.com/Azure/aks-engine/master/examples/kubernetes-vmss/kubernetes.json
W1126 19:00:57.376] 2019/11/26 19:00:57 azure.go:727: Docker logout.
W1126 19:00:57.434] 2019/11/26 19:00:57 azure.go:959: Deleting resource group: kubetest-1e7c5701-107e-11ea-99b0-02423d69ff80.
W1126 19:00:57.464] 2019/11/26 19:00:57 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml.
W1126 19:00:57.464] 2019/11/26 19:00:57 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
W1126 19:00:58.163] 2019/11/26 19:00:58 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 698.805083ms
W1126 19:00:58.165] panic: runtime error: invalid memory address or nil pointer dereference
W1126 19:00:58.166] [signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x157e0cd]
W1126 19:00:58.166] 
W1126 19:00:58.166] goroutine 1 [running]:
W1126 19:00:58.166] main.(*Cluster).populateApiModelTemplate(0xc0000bdd40, 0x62, 0xc000230120)
W1126 19:00:58.166] 	/workspace/kubetest/azure.go:504 +0x53d
W1126 19:00:58.167] main.Cluster.Up(0x1d750a0, 0xc0000d8000, 0xc0000e07e0, 0x7fffcdcbef1a, 0x7, 0xc0000d62a0, 0x2d, 0xc0000d62a0, 0x2d, 0x7fffcdcbef6f, ...)
W1126 19:00:58.167] 	/workspace/kubetest/azure.go:932 +0x157
W1126 19:00:58.167] k8s.io/test-infra/kubetest/process.(*Control).XMLWrap(0xc00024fe80, 0x29f3240, 0x1a141f5, 0x2, 0xc0003a5450, 0x0, 0x0)
W1126 19:00:58.167] 	/workspace/kubetest/process/process.go:103 +0x7b
W1126 19:00:58.167] main.run(0x1d88fc0, 0xc0000bc9c0, 0x7fffcdcbed78, 0x7, 0x10000, 0x7fffcdcbedc5, 0xd, 0x0, 0x0, 0x7fffcdcbeda0, ...)
W1126 19:00:58.167] 	/workspace/kubetest/e2e.go:115 +0x491
W1126 19:00:58.168] main.complete(0xc0000c6380, 0x0, 0x0)
W1126 19:00:58.168] 	/workspace/kubetest/main.go:401 +0x461
W1126 19:00:58.168] main.main()
W1126 19:00:58.168] 	/workspace/kubetest/main.go:310 +0x3ef
W1126 19:00:58.168] Traceback (most recent call last):
W1126 19:00:58.168]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module>
W1126 19:00:58.168]     main(parse_args())
W1126 19:00:58.169]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main
W1126 19:00:58.169]     mode.start(runner_args)
W1126 19:00:58.169]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start
W1126 19:00:58.169]     check_env(env, self.command, *args)
W1126 19:00:58.169]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env
W1126 19:00:58.169]     subprocess.check_call(cmd, env=env)
W1126 19:00:58.169]   File "/usr/lib/python2.7/subprocess.py", line 190, in check_call
W1126 19:00:58.170]     raise CalledProcessError(retcode, cmd)
W1126 19:00:58.170] subprocess.CalledProcessError: Command '('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=host-go', '--up', '--down', '--test', '--deployment=acsengine', '--provider=azure', '--cluster=bootstrap-e2e', '--gcp-network=bootstrap-e2e', '--ginkgo-parallel=10', '--acsengine-agentpoolcount=2', '--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-location=westus2', '--acsengine-public-key=/etc/azure-ssh/azure-ssh-pub', '--acsengine-template-url=https://raw.githubusercontent.com/Azure/aks-engine/master/examples/kubernetes-vmss/kubernetes.json', '--acsengine-download-url=https://aka.ms/aks-engine/aks-engine-k8s-e2e.tar.gz', '--test_args=--ginkgo.focus=azure-disk --ginkgo.skip=\\[Slow\\]|\\[Serial\\]|\\[Disruptive\\]|\\[Flaky\\]|\\[Feature:.+\\]', '--timeout=420m')' returned non-zero exit status 2
E1126 19:00:58.176] Command failed
I1126 19:00:58.176] process 719 exited with code 1 after 6.9m
E1126 19:00:58.176] FAIL: chewong-in-tree-azure-disk-e2e
I1126 19:00:58.176] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1126 19:00:58.969] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1126 19:00:59.001] process 13926 exited with code 0 after 0.0m
I1126 19:00:59.001] Call:  gcloud config get-value account
I1126 19:00:59.255] process 13939 exited with code 0 after 0.0m
I1126 19:00:59.256] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1126 19:00:59.256] Upload result and artifacts...
I1126 19:00:59.256] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120
I1126 19:00:59.256] Call:  gsutil ls gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120/artifacts
W1126 19:01:00.281] CommandException: One or more URLs matched no objects.
E1126 19:01:00.356] Command failed
I1126 19:01:00.356] process 13952 exited with code 1 after 0.0m
W1126 19:01:00.356] Remote dir gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120/artifacts not exist yet
I1126 19:01:00.356] Call:  gsutil -m -q -o GSUtil:use_magicfile=True cp -r -c -z log,txt,xml /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120/artifacts
I1126 19:01:01.910] process 14097 exited with code 0 after 0.0m
I1126 19:01:01.910] Call:  git rev-parse HEAD
I1126 19:01:01.913] process 14624 exited with code 0 after 0.0m
I1126 19:01:01.913] Call:  git rev-parse HEAD
I1126 19:01:01.917] process 14625 exited with code 0 after 0.0m
I1126 19:01:01.917] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/directory/chewong-in-tree-azure-disk-e2e/jobResultsCache.json
I1126 19:01:02.863] process 14626 exited with code 0 after 0.0m
I1126 19:01:02.863] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/chewong-in-tree-azure-disk-e2e/jobResultsCache.json#1574794224607690'
I1126 19:01:03.930] process 14771 exited with code 0 after 0.0m
I1126 19:01:03.931] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1574794224607690 cp /tmp/gsutil_HeI39v gs://kubernetes-upstream/pr-logs/directory/chewong-in-tree-azure-disk-e2e/jobResultsCache.json
I1126 19:01:05.155] process 14918 exited with code 0 after 0.0m
I1126 19:01:05.155] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/jobResultsCache.json
I1126 19:01:05.978] process 15099 exited with code 0 after 0.0m
I1126 19:01:05.979] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/jobResultsCache.json#1574794227732738'
I1126 19:01:06.977] process 15244 exited with code 0 after 0.0m
I1126 19:01:06.977] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1574794227732738 cp /tmp/gsutil_XrhcEk gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/jobResultsCache.json
I1126 19:01:08.222] process 15391 exited with code 0 after 0.0m
I1126 19:01:08.223] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_06_GQ2 gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/1199400605160837120/finished.json
I1126 19:01:09.458] process 15572 exited with code 0 after 0.0m
I1126 19:01:09.458] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_itMq3G gs://kubernetes-upstream/pr-logs/directory/chewong-in-tree-azure-disk-e2e/latest-build.txt
I1126 19:01:10.681] process 15753 exited with code 0 after 0.0m
I1126 19:01:10.682] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_kEGr1V gs://kubernetes-upstream/pr-logs/pull/85621/chewong-in-tree-azure-disk-e2e/latest-build.txt
I1126 19:01:11.985] process 15934 exited with code 0 after 0.0m