W1016 18:52:43.432] **************************************************************************
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 18:52:43.433] 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: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.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz --timeout=420m
I1016 18:52:43.433] Bootstrap chewong-e2e-ccm...
I1016 18:52:43.436] Builder: 038b042f-f046-11e9-918b-16773c0c7aed
I1016 18:52:43.436] Image: chewong/kubekins-e2e:v20191016-test
I1016 18:52:43.437] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128
I1016 18:52:43.437] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1016 18:52:43.945] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1016 18:52:43.976] process 215 exited with code 0 after 0.0m
I1016 18:52:43.977] Call:  gcloud config get-value account
I1016 18:52:44.212] process 227 exited with code 0 after 0.0m
I1016 18:52:44.213] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1016 18:52:44.213] Root: /go/src
I1016 18:52:44.213] cd to /go/src
I1016 18:52:44.213] Checkout: /go/src/k8s.io/kubernetes release-1.16 to /go/src/k8s.io/kubernetes
I1016 18:52:44.214] Call:  git init k8s.io/kubernetes
I1016 18:52:44.217] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/
I1016 18:52:44.217] process 239 exited with code 0 after 0.0m
I1016 18:52:44.218] Call:  git config --local user.name 'K8S Bootstrap'
I1016 18:52:44.220] process 240 exited with code 0 after 0.0m
I1016 18:52:44.220] Call:  git config --local user.email k8s_bootstrap@localhost
I1016 18:52:44.222] process 241 exited with code 0 after 0.0m
I1016 18:52:44.222] Call:  git fetch --quiet --tags https://github.com/kubernetes/kubernetes release-1.16
I1016 18:53:38.043] process 242 exited with code 0 after 0.9m
I1016 18:53:38.044] Call:  git checkout -B test FETCH_HEAD
W1016 18:53:40.124] Switched to a new branch 'test'
I1016 18:53:40.133] process 254 exited with code 0 after 0.0m
I1016 18:53:40.133] Call:  git show -s --format=format:%ct HEAD
I1016 18:53:40.137] process 255 exited with code 0 after 0.0m
I1016 18:53:40.137] Checkout: /go/src/k8s.io/cloud-provider-azure master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:95c5c01d4ae3237e932ed7bae98f82bd66987c26 to /go/src/k8s.io/cloud-provider-azure
I1016 18:53:40.138] Call:  git init k8s.io/cloud-provider-azure
I1016 18:53:40.142] Initialized empty Git repository in /go/src/k8s.io/cloud-provider-azure/.git/
I1016 18:53:40.142] process 256 exited with code 0 after 0.0m
I1016 18:53:40.142] Call:  git config --local user.name 'K8S Bootstrap'
I1016 18:53:40.145] process 257 exited with code 0 after 0.0m
I1016 18:53:40.146] Call:  git config --local user.email k8s_bootstrap@localhost
I1016 18:53:40.148] process 258 exited with code 0 after 0.0m
I1016 18:53:40.148] Call:  git fetch --quiet --tags https://github.com/kubernetes/cloud-provider-azure master +refs/pull/248/head:refs/pr/248
I1016 18:53:41.626] process 259 exited with code 0 after 0.0m
I1016 18:53:41.626] Call:  git checkout -B test c470e6f36d76e5a565478fcba22118c06bc1548f
W1016 18:53:42.033] Switched to a new branch 'test'
I1016 18:53:42.036] process 271 exited with code 0 after 0.0m
I1016 18:53:42.036] Call:  git show -s --format=format:%ct HEAD
I1016 18:53:42.039] process 272 exited with code 0 after 0.0m
I1016 18:53:42.039] Call:  git merge --no-ff -m 'Merge +refs/pull/248/head:refs/pr/248' 95c5c01d4ae3237e932ed7bae98f82bd66987c26
I1016 18:53:42.102] Merge made by the 'recursive' strategy.
I1016 18:53:42.104]  hack/log-dump.sh | 161 +++++++++++++++++++++++++++++++++++++++++++++++++++++++
I1016 18:53:42.104]  1 file changed, 161 insertions(+)
I1016 18:53:42.104]  create mode 100755 hack/log-dump.sh
I1016 18:53:42.104] process 273 exited with code 0 after 0.0m
I1016 18:53:42.105] Configure environment...
I1016 18:53:42.105] Call:  git show -s --format=format:%ct HEAD
I1016 18:53:42.108] process 275 exited with code 0 after 0.0m
I1016 18:53:42.108] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1016 18:53:42.740] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1016 18:53:42.853] process 276 exited with code 0 after 0.0m
I1016 18:53:42.853] Call:  gcloud config get-value account
I1016 18:53:43.091] process 288 exited with code 0 after 0.0m
I1016 18:53:43.092] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1016 18:53:43.092] 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 18:53:43.264] process 300 exited with code 0 after 0.0m
I1016 18:53:43.264] Start 1184542576745648128 at v1.16.3-beta.0.5+4209b9f168d0e3...
I1016 18:53:43.266] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil__ZsmAI gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128/started.json
I1016 18:53:44.712] process 333 exited with code 0 after 0.0m
I1016 18:53:44.713] 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/1184542576745648128' cp /tmp/gsutil_OnPucN gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/1184542576745648128.txt
I1016 18:53:46.001] process 511 exited with code 0 after 0.0m
I1016 18:53:46.002] 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.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz --timeout=420m
W1016 18:53:46.039] starts with local mode
W1016 18:53:46.040] Environment:
W1016 18:53:46.040] ARTIFACTS=/workspace/_artifacts
W1016 18:53:46.040] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa
W1016 18:53:46.040] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub
W1016 18:53:46.040] AZURE_CREDENTIALS=/etc/azure-cred/credentials
W1016 18:53:46.040] AZURE_SSH_PRIVATE_KEY_FILE=/etc/azure-ssh/azure-ssh
W1016 18:53:46.040] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub
W1016 18:53:46.041] AZURE_SSH_USER=azureuser
W1016 18:53:46.041] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer
W1016 18:53:46.041] BAZEL_REMOTE_CACHE_ENABLED=false
W1016 18:53:46.041] BAZEL_VERSION=0.23.2
W1016 18:53:46.041] BOOTSTRAP_MIGRATION=yes
W1016 18:53:46.041] BUILD_ID=1184542576745648128
W1016 18:53:46.041] BUILD_NUMBER=1184542576745648128
W1016 18:53:46.042] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true
W1016 18:53:46.042] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud
W1016 18:53:46.042] CLOUDSDK_CORE_DISABLE_PROMPTS=1
W1016 18:53:46.042] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false
W1016 18:53:46.042] CLOUD_CONFIG=random
W1016 18:53:46.042] DECK_PORT=tcp://10.0.160.83:80
W1016 18:53:46.042] DECK_PORT_80_TCP=tcp://10.0.160.83:80
W1016 18:53:46.043] DECK_PORT_80_TCP_ADDR=10.0.160.83
W1016 18:53:46.043] DECK_PORT_80_TCP_PORT=80
W1016 18:53:46.043] DECK_PORT_80_TCP_PROTO=tcp
W1016 18:53:46.043] DECK_SERVICE_HOST=10.0.160.83
W1016 18:53:46.043] DECK_SERVICE_PORT=80
W1016 18:53:46.043] DOCKER_IN_DOCKER_ENABLED=true
W1016 18:53:46.043] DOCKER_IN_DOCKER_IPV6_ENABLED=false
W1016 18:53:46.043] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128/artifacts
W1016 18:53:46.044] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json
W1016 18:53:46.044] GOPATH=/go
W1016 18:53:46.044] GO_TARBALL=go1.12.10.linux-amd64.tar.gz
W1016 18:53:46.044] HOME=/workspace
W1016 18:53:46.044] HOOK_PORT=tcp://10.0.144.133:8888
W1016 18:53:46.044] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888
W1016 18:53:46.044] HOOK_PORT_8888_TCP_ADDR=10.0.144.133
W1016 18:53:46.045] HOOK_PORT_8888_TCP_PORT=8888
W1016 18:53:46.045] HOOK_PORT_8888_TCP_PROTO=tcp
W1016 18:53:46.045] HOOK_SERVICE_HOST=10.0.144.133
W1016 18:53:46.045] HOOK_SERVICE_PORT=8888
W1016 18:53:46.045] HOSTNAME=038b042f-f046-11e9-918b-16773c0c7aed
W1016 18:53:46.045] IMAGE=chewong/kubekins-e2e:v20191016-test
W1016 18:53:46.045] INSTANCE_PREFIX=bootstrap-e2e
W1016 18:53:46.046] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine
W1016 18:53:46.046] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub
W1016 18:53:46.046] JOB_NAME=chewong-e2e-ccm
W1016 18:53:46.046] JOB_SPEC={"type":"presubmit","job":"chewong-e2e-ccm","buildid":"1184542576745648128","prowjobid":"038b042f-f046-11e9-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"064458de46189749da9102015312b857c47c963d","base_link":"https://github.com/Azure/kubernetes/commit/064458de46189749da9102015312b857c47c963d","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 18:53:46.046] JOB_TYPE=presubmit
W1016 18:53:46.047] KUBERNETES_PORT=tcp://10.0.0.1:443
W1016 18:53:46.047] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443
W1016 18:53:46.047] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1
W1016 18:53:46.047] KUBERNETES_PORT_443_TCP_PORT=443
W1016 18:53:46.047] KUBERNETES_PORT_443_TCP_PROTO=tcp
W1016 18:53:46.047] KUBERNETES_SERVICE_HOST=10.0.0.1
W1016 18:53:46.047] KUBERNETES_SERVICE_PORT=443
W1016 18:53:46.048] KUBERNETES_SERVICE_PORT_HTTPS=443
W1016 18:53:46.048] KUBETEST_IN_DOCKER=true
W1016 18:53:46.048] KUBETEST_MANUAL_DUMP=y
W1016 18:53:46.048] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e
W1016 18:53:46.048] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e
W1016 18:53:46.048] KUBE_VERBOSE=0
W1016 18:53:46.048] NODE_NAME=038b042f-f046-11e9-918b-16773c0c7aed
W1016 18:53:46.049] 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 18:53:46.049] PROW_JOB_ID=038b042f-f046-11e9-918b-16773c0c7aed
W1016 18:53:46.049] PULL_BASE_REF=master
W1016 18:53:46.049] PULL_BASE_SHA=064458de46189749da9102015312b857c47c963d
W1016 18:53:46.049] PULL_NUMBER=113
W1016 18:53:46.049] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822
W1016 18:53:46.050] PULL_REFS=master:064458de46189749da9102015312b857c47c963d,113:879465972041635fd7bc8269da49153b67e63822
W1016 18:53:46.050] PWD=/workspace
W1016 18:53:46.050] REGISTRY=k8sprowinternal.azurecr.io
W1016 18:53:46.050] REPO_NAME=kubernetes
W1016 18:53:46.050] REPO_OWNER=Azure
W1016 18:53:46.050] SHLVL=2
W1016 18:53:46.051] SOURCE_DATE_EPOCH=1571248530
W1016 18:53:46.051] TERM=xterm
W1016 18:53:46.051] TIDE_PORT=tcp://10.0.180.53:80
W1016 18:53:46.051] TIDE_PORT_80_TCP=tcp://10.0.180.53:80
W1016 18:53:46.051] TIDE_PORT_80_TCP_ADDR=10.0.180.53
W1016 18:53:46.052] TIDE_PORT_80_TCP_PORT=80
W1016 18:53:46.052] TIDE_PORT_80_TCP_PROTO=tcp
W1016 18:53:46.052] TIDE_SERVICE_HOST=10.0.180.53
W1016 18:53:46.052] TIDE_SERVICE_PORT=80
W1016 18:53:46.052] WORKSPACE=/workspace
W1016 18:53:46.053] _=./test-infra/jenkins/bootstrap.py
W1016 18:53:46.053] 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.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz', '--timeout=420m')
W1016 18:53:46.055] 2019/10/16 18:53:46 main.go:332: Limiting testing to 7h0m0s
W1016 18:53:46.055] 2019/10/16 18:53:46 azure.go:232: Reading credentials file /etc/azure-cred/credentials
W1016 18:53:46.055] 2019/10/16 18:53:46 process.go:153: Running: make -C /go/src/k8s.io/kubernetes bazel-release
W1016 18:53:46.070] Extracting Bazel installation...
I1016 18:53:46.170] make: Entering directory '/go/src/k8s.io/kubernetes'
W1016 18:53:54.602] Starting local Bazel server and connecting to it...
W1016 18:53:56.476] Loading: 
W1016 18:53:56.479] Loading: 0 packages loaded
W1016 18:53:57.482] Loading: 0 packages loaded
W1016 18:53:59.064] Loading: 0 packages loaded
W1016 18:54:00.483] Loading: 0 packages loaded
W1016 18:54:02.470] Loading: 0 packages loaded
W1016 18:54:03.483] Loading: 0 packages loaded
W1016 18:54:03.483]     currently loading: build/release-tars
W1016 18:54:05.899] Loading: 0 packages loaded
W1016 18:54:05.899]     currently loading: build/release-tars
W1016 18:54:06.262] Analyzing: target //build/release-tars:release-tars (1 packages loaded, 0 targets configured)
W1016 18:54:07.753] Analyzing: target //build/release-tars:release-tars (155 packages loaded, 1011 targets configured)
W1016 18:54:09.473] Analyzing: target //build/release-tars:release-tars (834 packages loaded, 3494 targets configured)
W1016 18:54:11.443] Analyzing: target //build/release-tars:release-tars (1615 packages loaded, 9540 targets configured)
W1016 18:54:13.714] Analyzing: target //build/release-tars:release-tars (2453 packages loaded, 20577 targets configured)
W1016 18:54:16.343] Analyzing: target //build/release-tars:release-tars (2823 packages loaded, 25040 targets configured)
W1016 18:54:19.523] Analyzing: target //build/release-tars:release-tars (3058 packages loaded, 27828 targets configured)
W1016 18:54:23.228] Analyzing: target //build/release-tars:release-tars (3071 packages loaded, 34088 targets configured)
W1016 18:54:31.297] Analyzing: target //build/release-tars:release-tars (3077 packages loaded, 37367 targets configured)
W1016 18:54:44.131] INFO: Analysed target //build/release-tars:release-tars (3077 packages loaded, 42527 targets configured).
W1016 18:54:44.133] Building: checking cached actions
W1016 18:54:44.134] INFO: Found 1 target...
W1016 18:54:44.838] [0 / 20] [-----] BazelWorkspaceStatusAction stable-status.txt ... (2 actions, 0 running)
W1016 18:54:44.839] [0 / 20] [-----] BazelWorkspaceStatusAction stable-status.txt ... (2 actions, 0 running)
W1016 18:54:53.130] [130 / 5,304] GoCompile vendor/github.com/coreos/bbolt/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/coreos/bbolt.a; 1s linux-sandbox ... (8 actions, 7 running)
W1016 18:55:01.675] [443 / 5,304] GoCompile vendor/github.com/stretchr/objx/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/stretchr/objx.a; 0s linux-sandbox ... (7 actions, 6 running)
W1016 18:55:11.880] [575 / 5,304] GoCompile vendor/gonum.org/v1/gonum/internal/asm/f32/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/gonum.org/v1/gonum/internal/asm/f32.a~partial.a; 2s linux-sandbox ... (8 actions, 7 running)
W1016 18:55:23.957] [658 / 5,304] GoCompile vendor/gonum.org/v1/gonum/graph/formats/dot/internal/parser/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/gonum.org/v1/gonum/graph/formats/dot/internal/parser.a; 2s linux-sandbox ... (8 actions running)
W1016 18:55:37.100] [776 / 5,304] Compiling vendor/golang.org/x/sys/unix/linux_amd64_stripped/go_default_library%linux_amd64%cgo_codegen%/endian_big.cgo2.c; 0s linux-sandbox ... (8 actions running)
W1016 18:55:52.266] [1,125 / 5,304] GoCompile vendor/github.com/Azure/go-autorest/autorest/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/Azure/go-autorest/autorest.a; 0s linux-sandbox ... (8 actions, 7 running)
W1016 18:56:10.176] [1,305 / 5,304] GoCompile vendor/github.com/spf13/pflag/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/spf13/pflag.a; 4s linux-sandbox ... (8 actions, 7 running)
W1016 18:56:31.276] [1,540 / 5,304] GoCompile pkg/util/mount/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/pkg/util/mount.a; 1s linux-sandbox ... (8 actions, 7 running)
W1016 18:56:55.325] [1,723 / 5,304] GoCompile vendor/github.com/vmware/govmomi/vim25/types/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/types.a; 14s linux-sandbox ... (8 actions, 7 running)
W1016 18:57:22.246] [1,867 / 5,304] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 26s linux-sandbox ... (8 actions, 7 running)
W1016 18:57:53.227] [1,990 / 5,304] GoCompile vendor/github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud.a; 9s linux-sandbox ... (8 actions, 7 running)
W1016 18:58:29.456] [2,205 / 5,304]  <rule context for //staging/src/k8s.io/sample-apiserver/pkg/generated/openapi:zz_generated.openapi>; 3s linux-sandbox ... (8 actions, 7 running)
W1016 18:59:10.626] [2,465 / 5,304] 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; 1s linux-sandbox ... (8 actions, 7 running)
W1016 18:59:58.522] [2,638 / 5,304] PackageTar build/release-tars/kubernetes-src.tar.gz; 6s linux-sandbox ... (8 actions, 7 running)
W1016 19:00:52.903] [2,894 / 5,304] GoCompile vendor/gonum.org/v1/gonum/graph/simple/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/gonum.org/v1/gonum/graph/simple.a; 1s linux-sandbox ... (8 actions, 7 running)
W1016 19:01:55.894] [3,254 / 5,304] GoLink cmd/gendocs/gendocs; 4s linux-sandbox ... (8 actions, 7 running)
W1016 19:03:09.685] [3,524 / 5,304] GoCompile pkg/apis/policy/validation/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/pkg/apis/policy/validation.a; 5s linux-sandbox ... (8 actions, 7 running)
W1016 19:04:34.557] [4,077 / 5,304] GoCompile vendor/github.com/Azure/azure-sdk-for-go/services/storage/mgmt/2019-04-01/storage/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/Azure/azure-sdk-for-go/services/storage/mgmt/2019-04-01/storage.a; 5s linux-sandbox ... (8 actions, 7 running)
W1016 19:06:12.628] [4,720 / 5,304] GoCompile staging/src/k8s.io/client-go/listers/batch/v1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/listers/batch/v1.a; 2s linux-sandbox ... (8 actions, 7 running)
W1016 19:08:04.261] [5,110 / 5,304] GoLink test/e2e_node/linux_amd64_stripped/_go_default_test-cgo; 32s linux-sandbox ... (8 actions, 7 running)
W1016 19:10:14.531] [5,250 / 5,304] GoLink cmd/genman/genman; 107s linux-sandbox ... (8 actions running)
W1016 19:11:45.172] Slow read: a 51889574-byte read from /workspace/.cache/bazel/_bazel_root/48d5366022b4e3197674c8d6e2bee219/execroot/io_k8s_kubernetes/bazel-out/k8-fastbuild/bin/cmd/kube-scheduler/linux_amd64_pure_stripped/kube-scheduler took 25313 ms.
W1016 19:12:31.900] Slow read: a 51892224-byte read from /workspace/.cache/bazel/_bazel_root/48d5366022b4e3197674c8d6e2bee219/execroot/io_k8s_kubernetes/bazel-out/k8-fastbuild/bin/build/debs/kube-scheduler-deb-data-amd64-0.tar took 43102 ms.
W1016 19:12:50.168] [5,269 / 5,304] GoLink cmd/kube-apiserver/linux_amd64_pure_stripped/kube-apiserver; 135s linux-sandbox ... (5 actions, 4 running)
W1016 19:14:26.812] Target //build/release-tars:release-tars up-to-date:
W1016 19:14:26.813]   bazel-bin/build/release-tars/kubernetes-client-linux-amd64.tar.gz
W1016 19:14:26.813]   bazel-bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz
W1016 19:14:26.814]   bazel-bin/build/release-tars/kubernetes-server-linux-amd64.tar.gz
W1016 19:14:26.814]   bazel-bin/build/release-tars/kubernetes-manifests.tar.gz
W1016 19:14:26.818]   bazel-bin/build/release-tars/kubernetes-test-portable.tar.gz
W1016 19:14:26.818]   bazel-bin/build/release-tars/kubernetes-test-linux-amd64.tar.gz
W1016 19:14:26.819]   bazel-bin/build/release-tars/kubernetes-test.tar.gz
W1016 19:14:26.819]   bazel-bin/build/release-tars/kubernetes.tar.gz
W1016 19:14:26.820]   bazel-bin/build/release-tars/kubernetes-src.tar.gz
W1016 19:14:26.850] INFO: Elapsed time: 1240.734s, Critical Path: 456.63s
W1016 19:14:26.851] INFO: 5211 processes: 5211 linux-sandbox.
W1016 19:14:26.857] INFO: Build completed successfully, 5304 total actions
W1016 19:14:26.859] INFO: Build completed successfully, 5304 total actions
W1016 19:14:26.900] 2019/10/16 19:14:26 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes bazel-release' finished in 20m40.844986106s
W1016 19:14:26.900] 2019/10/16 19:14:26 util.go:277: Flushing memory.
I1016 19:14:27.001] make: Leaving directory '/go/src/k8s.io/kubernetes'
W1016 19:14:54.899] 2019/10/16 19:14:54 azure.go:906: Deleting resource group: kubetest-4829425a-f046-11e9-97ea-0242873e7a00.
W1016 19:14:55.430] 2019/10/16 19:14:55 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1016 19:14:55.431] 2019/10/16 19:14:55 azure.go:673: Attempting Docker login with azure cred.
W1016 19:14:56.942] 2019/10/16 19:14:56 azure.go:682: Docker login success.
W1016 19:14:56.943] 2019/10/16 19:14:56 azure.go:697: Building ccm.
W1016 19:14:56.943] 2019/10/16 19:14:56 azure.go:699: projectPath /go/src/k8s.io/cloud-provider-azure
W1016 19:14:56.943] 2019/10/16 19:14:56 process.go:153: Running: docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184542576745648128-3cc491e2 .
I1016 19:14:59.107] Sending build context to Docker daemon  67.18MB

I1016 19:14:59.153] Step 1/7 : FROM golang:1.12.9-stretch AS build
I1016 19:15:00.081] 1.12.9-stretch: Pulling from library/golang
I1016 19:15:00.419] 092586df9206: Pulling fs layer
I1016 19:15:00.419] ef599477fae0: Pulling fs layer
I1016 19:15:00.419] 4530c6472b5d: Pulling fs layer
I1016 19:15:00.419] d34d61487075: Pulling fs layer
I1016 19:15:00.420] 89c6ec31b9e9: Pulling fs layer
I1016 19:15:00.420] e37857ebcafa: Pulling fs layer
I1016 19:15:00.420] b0e29f6c7f0a: Pulling fs layer
I1016 19:15:00.420] d34d61487075: Waiting
I1016 19:15:00.420] 89c6ec31b9e9: Waiting
I1016 19:15:00.420] e37857ebcafa: Waiting
I1016 19:15:00.420] b0e29f6c7f0a: Waiting
I1016 19:15:00.889] 4530c6472b5d: Verifying Checksum
I1016 19:15:00.889] 4530c6472b5d: Download complete
I1016 19:15:00.937] ef599477fae0: Verifying Checksum
I1016 19:15:00.937] ef599477fae0: Download complete
I1016 19:15:01.300] 092586df9206: Download complete
I1016 19:15:01.812] d34d61487075: Verifying Checksum
I1016 19:15:01.813] d34d61487075: Download complete
I1016 19:15:02.133] 89c6ec31b9e9: Verifying Checksum
I1016 19:15:02.133] 89c6ec31b9e9: Download complete
I1016 19:15:02.215] b0e29f6c7f0a: Verifying Checksum
I1016 19:15:02.216] b0e29f6c7f0a: Download complete
I1016 19:15:03.466] e37857ebcafa: Download complete
I1016 19:15:04.510] 092586df9206: Pull complete
I1016 19:15:05.288] ef599477fae0: Pull complete
I1016 19:15:05.651] 4530c6472b5d: Pull complete
I1016 19:15:09.273] d34d61487075: Pull complete
I1016 19:15:12.767] 89c6ec31b9e9: Pull complete
I1016 19:15:20.420] e37857ebcafa: Pull complete
I1016 19:15:20.611] b0e29f6c7f0a: Pull complete
I1016 19:15:20.635] Digest: sha256:76b52857546f070cc3ac499accb27b8c411b10ff6d45c0b1da2a8aab7b61fe29
I1016 19:15:20.652] Status: Downloaded newer image for golang:1.12.9-stretch
I1016 19:15:20.652]  ---> 2c4a601e5da9
I1016 19:15:20.653] Step 2/7 : WORKDIR /go/src/k8s.io/cloud-provider-azure
I1016 19:15:32.179]  ---> Running in 182570de1cd8
I1016 19:15:33.354] Removing intermediate container 182570de1cd8
I1016 19:15:33.354]  ---> b9d9fc27e312
I1016 19:15:33.354] Step 3/7 : COPY . .
I1016 19:15:39.152]  ---> 88c87c413ed1
I1016 19:15:39.152] Step 4/7 : RUN make
I1016 19:15:39.332]  ---> Running in 9b95c7849b9c
I1016 19:15:40.211] hack/pkg-config.sh > .pkg_config
I1016 19:15:40.240] 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-16T19:15:40Z' ./cmd/cloud-controller-manager
I1016 19:16:22.056] 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-16T19:15:40Z' ./cmd/cloud-node-manager
I1016 19:16:45.778] Removing intermediate container 9b95c7849b9c
I1016 19:16:45.779]  ---> fd601ed3bab8
I1016 19:16:45.779] Step 5/7 : FROM k8s.gcr.io/debian-base:v1.0.0
I1016 19:16:46.070] v1.0.0: Pulling from debian-base
I1016 19:16:46.233] 39fafc05754f: Pulling fs layer
I1016 19:16:46.659] 39fafc05754f: Verifying Checksum
I1016 19:16:46.660] 39fafc05754f: Download complete
I1016 19:16:49.062] 39fafc05754f: Pull complete
I1016 19:16:49.085] Digest: sha256:3801f944c765dc1b54900826ca67b1380bb8c73b9caf4a2a27ce613b3ba3e742
I1016 19:16:49.104] Status: Downloaded newer image for k8s.gcr.io/debian-base:v1.0.0
I1016 19:16:49.104]  ---> 204e96332c91
I1016 19:16:49.104] Step 6/7 : COPY --from=build /go/src/k8s.io/cloud-provider-azure/bin/azure-cloud-controller-manager /usr/local/bin
I1016 19:16:52.035]  ---> 2f30c940063b
I1016 19:16:52.036] Step 7/7 : RUN ln -s /usr/local/bin/azure-cloud-controller-manager /usr/local/bin/cloud-controller-manager
I1016 19:16:52.191]  ---> Running in 42391d05b391
I1016 19:16:54.065] Removing intermediate container 42391d05b391
I1016 19:16:54.065]  ---> 25a61bc7f1a2
I1016 19:16:54.183] Successfully built 25a61bc7f1a2
I1016 19:16:54.287] Successfully tagged k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184542576745648128-3cc491e2
W1016 19:16:54.388] 2019/10/16 19:16:54 process.go:155: Step 'docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184542576745648128-3cc491e2 .' finished in 1m57.348690375s
W1016 19:16:54.388] 2019/10/16 19:16:54 process.go:153: Running: docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184542576745648128-3cc491e2
W1016 19:16:58.168] 2019/10/16 19:16:58 process.go:155: Step 'docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184542576745648128-3cc491e2' finished in 3.876704932s
W1016 19:16:58.168] 2019/10/16 19:16:58 azure.go:686: Docker logout.
W1016 19:16:58.225] 2019/10/16 19:16:58 azure.go:716: Custom cloud controller manager URL: k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1184542576745648128-3cc491e2 .
W1016 19:16:58.225] 2019/10/16 19:16:58 azure.go:654: CWD /go/src/k8s.io/kubernetes
W1016 19:16:58.225] 2019/10/16 19:16:58 azure.go:673: Attempting Docker login with azure cred.
W1016 19:16:59.095] 2019/10/16 19:16:59 azure.go:682: Docker login success.
W1016 19:16:59.095] 2019/10/16 19:16:59 azure.go:726: Building hyperkube.
W1016 19:16:59.096] 2019/10/16 19:16:59 process.go:153: Running: make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube
W1016 19:17:24.397] found packages rand (cgo1.go) and rand2 (cgo2.go) in /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/bazel-kubernetes/external/go_sdk/doc/progs
W1016 19:20:03.367] 2019/10/16 19:20:03 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube' finished in 3m4.272209704s
W1016 19:20:03.368] 2019/10/16 19:20:03 azure.go:733: Pushing hyperkube.
W1016 19:20:03.368] 2019/10/16 19:20:03 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
I1016 19:20:03.468] make: Entering directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
I1016 19:20:03.468] cp -r ./* /tmp/hyperkubeUWVYAq
I1016 19:20:03.469] cp /go/src/k8s.io/kubernetes/_output/bin/hyperkube /tmp/hyperkubeUWVYAq
I1016 19:20:03.550] chmod a+rx /tmp/hyperkubeUWVYAq/hyperkube
I1016 19:20:03.552] cd /tmp/hyperkubeUWVYAq && sed -i.back "s|BASEIMAGE|k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1|g" Dockerfile
I1016 19:20:03.554] docker build --pull -t k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184542576745648128-85f58cdd /tmp/hyperkubeUWVYAq
I1016 19:20:04.734] Sending build context to Docker daemon  212.1MB

I1016 19:20:04.770] Step 1/2 : FROM k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1016 19:20:05.058] 0.12.1: Pulling from debian-hyperkube-base-amd64
I1016 19:20:05.058] 346aee5ea5bc: Pulling fs layer
I1016 19:20:05.058] 9c47fde751af: Pulling fs layer
I1016 19:20:05.058] be2693a52daf: Pulling fs layer
I1016 19:20:05.059] 6b69eb11d043: Pulling fs layer
I1016 19:20:05.059] 0abeb1500767: Pulling fs layer
I1016 19:20:05.059] 4062d80041b7: Pulling fs layer
I1016 19:20:05.059] 23b6daf06fc2: Pulling fs layer
I1016 19:20:05.059] 0abeb1500767: Waiting
I1016 19:20:05.060] 4062d80041b7: Waiting
I1016 19:20:05.060] 23b6daf06fc2: Waiting
I1016 19:20:05.060] 6b69eb11d043: Waiting
I1016 19:20:05.349] 9c47fde751af: Download complete
I1016 19:20:05.358] be2693a52daf: Verifying Checksum
I1016 19:20:05.359] be2693a52daf: Download complete
I1016 19:20:05.566] 6b69eb11d043: Download complete
I1016 19:20:05.587] 346aee5ea5bc: Verifying Checksum
I1016 19:20:05.587] 346aee5ea5bc: Download complete
I1016 19:20:05.606] 0abeb1500767: Download complete
I1016 19:20:06.143] 23b6daf06fc2: Verifying Checksum
I1016 19:20:06.143] 23b6daf06fc2: Download complete
I1016 19:20:07.461] 4062d80041b7: Verifying Checksum
I1016 19:20:07.461] 4062d80041b7: Download complete
I1016 19:20:07.652] 346aee5ea5bc: Pull complete
I1016 19:20:07.788] 9c47fde751af: Pull complete
I1016 19:20:07.979] be2693a52daf: Pull complete
I1016 19:20:08.179] 6b69eb11d043: Pull complete
I1016 19:20:08.326] 0abeb1500767: Pull complete
I1016 19:20:16.018] 4062d80041b7: Pull complete
I1016 19:20:17.006] 23b6daf06fc2: Pull complete
I1016 19:20:17.031] Digest: sha256:5d4ea2fb5fbe9a9a9da74f67cf2faefc881968bc39f2ac5d62d9167e575812a1
I1016 19:20:17.049] Status: Downloaded newer image for k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1
I1016 19:20:17.049]  ---> a46476511725
I1016 19:20:17.049] Step 2/2 : COPY hyperkube /hyperkube
I1016 19:20:40.933]  ---> fba4e63a999e
I1016 19:20:40.960] Successfully built fba4e63a999e
I1016 19:20:41.035] Successfully tagged k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184542576745648128-85f58cdd
I1016 19:20:41.038] rm -rf "/tmp/hyperkubeUWVYAq"
I1016 19:20:41.067] docker push k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184542576745648128-85f58cdd
I1016 19:20:41.138] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube-amd64]
I1016 19:20:41.165] 35ecfcbcbd7b: Preparing
I1016 19:20:41.166] 39b3ac6d96e9: Preparing
I1016 19:20:41.166] 7bbae4dddb88: Preparing
I1016 19:20:41.166] a00defcfe869: Preparing
I1016 19:20:41.166] 2ab0ae805c74: Preparing
I1016 19:20:41.166] 43a8fe7d2382: Preparing
I1016 19:20:41.166] 3f6a6f542637: Preparing
I1016 19:20:41.167] 5ba3be777c2d: Preparing
I1016 19:20:41.167] 43a8fe7d2382: Waiting
I1016 19:20:41.167] 3f6a6f542637: Waiting
I1016 19:20:41.167] 5ba3be777c2d: Waiting
I1016 19:20:41.397] 2ab0ae805c74: Layer already exists
I1016 19:20:41.418] 39b3ac6d96e9: Layer already exists
I1016 19:20:41.450] 7bbae4dddb88: Layer already exists
I1016 19:20:41.460] a00defcfe869: Layer already exists
I1016 19:20:41.511] 3f6a6f542637: Layer already exists
I1016 19:20:41.531] 43a8fe7d2382: Layer already exists
I1016 19:20:41.663] 5ba3be777c2d: Layer already exists
I1016 19:20:51.064] 35ecfcbcbd7b: Pushed
I1016 19:20:51.690] azure-e2e-1184542576745648128-85f58cdd: digest: sha256:32adcc89504a224bed26277c7f1adb16691b4afc0315252ed6b92c3115395743 size: 1998
I1016 19:20:51.702] docker rmi k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184542576745648128-85f58cdd 2>/dev/null || true
I1016 19:20:51.748] docker tag k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184542576745648128-85f58cdd k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184542576745648128-85f58cdd
I1016 19:20:51.811] docker push k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1184542576745648128-85f58cdd
I1016 19:20:51.873] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube]
I1016 19:20:51.886] 35ecfcbcbd7b: Preparing
I1016 19:20:51.886] 39b3ac6d96e9: Preparing
I1016 19:20:51.886] 7bbae4dddb88: Preparing
I1016 19:20:51.886] a00defcfe869: Preparing
I1016 19:20:51.886] 2ab0ae805c74: Preparing
I1016 19:20:51.887] 43a8fe7d2382: Preparing
I1016 19:20:51.887] 3f6a6f542637: Preparing
I1016 19:20:51.887] 5ba3be777c2d: Preparing
I1016 19:20:51.887] 43a8fe7d2382: Waiting
I1016 19:20:51.887] 3f6a6f542637: Waiting
I1016 19:20:51.887] 5ba3be777c2d: Waiting
I1016 19:20:51.995] 7bbae4dddb88: Layer already exists
I1016 19:20:52.036] a00defcfe869: Layer already exists
I1016 19:20:52.047] 39b3ac6d96e9: Layer already exists
I1016 19:20:52.057] 2ab0ae805c74: Layer already exists
I1016 19:20:52.068] 35ecfcbcbd7b: Mounted from hyperkube-amd64
I1016 19:20:52.079] 43a8fe7d2382: Layer already exists
I1016 19:20:52.125] 5ba3be777c2d: Layer already exists
I1016 19:20:52.146] 3f6a6f542637: Layer already exists
I1016 19:20:52.667] azure-e2e-1184542576745648128-85f58cdd: digest: sha256:32adcc89504a224bed26277c7f1adb16691b4afc0315252ed6b92c3115395743 size: 1998
I1016 19:20:52.682] make: Leaving directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube'
W1016 19:20:52.782] 2019/10/16 19:20:52 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes/cluster/images/hyperkube push HYPERKUBE_BIN=/go/src/k8s.io/kubernetes/_output/bin/hyperkube' finished in 49.314733926s
W1016 19:20:52.783] 2019/10/16 19:20:52 azure.go:686: Docker logout.
W1016 19:20:52.783] 2019/10/16 19:20:52 azure.go:744: Custom hyperkube URL: k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1184542576745648128-85f58cdd .
W1016 19:20:52.783] 2019/10/16 19:20:52 azure.go:787: downloading /workspace/aks916982188/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json.
W1016 19:20:52.783] 2019/10/16 19:20:52 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json
W1016 19:20:52.986] 2019/10/16 19:20:52 azure.go:529: downloading /workspace/aks-engine.tar.gz from https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz.
W1016 19:20:52.987] 2019/10/16 19:20:52 util.go:42: curl https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz
W1016 19:20:54.265] 2019/10/16 19:20:54 azure.go:556: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes .
W1016 19:20:54.266] 2019/10/16 19:20:54 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1
W1016 19:20:54.421] 2019/10/16 19:20:54 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 155.813067ms
W1016 19:20:54.422] 2019/10/16 19:20:54 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks916982188/kubernetes.json --output-directory /workspace/aks916982188
I1016 19:20:54.627] INFO[0000] Generating assets into /workspace/aks916982188... 
W1016 19:21:08.427] 2019/10/16 19:21:08 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks916982188/kubernetes.json --output-directory /workspace/aks916982188' finished in 14.00550259s
W1016 19:21:08.430] 2019/10/16 19:21:08 azure.go:627: Setting kubeconfig env variable: kubeconfig path: /workspace/aks916982188/kubeconfig/kubeconfig.eastus2.json.
W1016 19:21:08.430] 2019/10/16 19:21:08 azure.go:629: Creating resource group: kubetest-4829425a-f046-11e9-97ea-0242873e7a00.
W1016 19:21:08.430] 2019/10/16 19:21:08 azure.go:631: Creating Azure resource group: kubetest-4829425a-f046-11e9-97ea-0242873e7a00 for cluster deployment.
W1016 19:21:10.095] 2019/10/16 19:21:10 azure.go:636: Validating deployment ARM templates.
W1016 19:21:24.755] 2019/10/16 19:21:24 azure.go:642: Deploying cluster kubetest-4829425a-f046-11e9-97ea-0242873e7a00 in resource group kubetest-4829425a-f046-11e9-97ea-0242873e7a00.
W1016 19:37:35.592] 2019/10/16 19:37:35 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version
W1016 19:37:36.291] 2019/10/16 19:37:36 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 699.053278ms
W1016 19:37:36.291] 2019/10/16 19:37:36 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false get nodes -oyaml
W1016 19:37:37.608] 2019/10/16 19:37:37 process.go:155: Step './cluster/kubectl.sh --match-server-version=false get nodes -oyaml' finished in 1.317344677s
W1016 19:37:37.609] 2019/10/16 19:37:37 azure.go:962: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos.
W1016 19:37:37.609] 2019/10/16 19:37:37 azure.go:962: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos.
W1016 19:37:37.610] 2019/10/16 19:37:37 process.go:153: Running: kubectl get nodes --no-headers
W1016 19:37:38.233] 2019/10/16 19:37:38 process.go:155: Step 'kubectl get nodes --no-headers' finished in 622.593535ms
W1016 19:37:38.233] 2019/10/16 19:37:38 e2e.go:462: Cluster nodes:
W1016 19:37:38.233] k8s-agentpool1-16551099-0   Ready   agent    67s     v1.16.3-beta.0.5+4209b9f168d0e3
W1016 19:37:38.233] k8s-master-16551099-0       Ready   master   6m43s   v1.16.3-beta.0.5+4209b9f168d0e3
W1016 19:37:38.233] 2019/10/16 19:37:38 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version
W1016 19:37:38.674] 2019/10/16 19:37:38 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 441.176809ms
W1016 19:37:38.674] 2019/10/16 19:37:38 azure.go:916: Attempting to dump logs to /workspace/_artifacts
W1016 19:37:38.674] 2019/10/16 19:37:38 process.go:153: Running: bash -c hack/log-dump.sh /workspace/_artifacts
W1016 19:37:39.223] Warning: Identity file /etc/azure-ssh/azure-ssh not accessible: No such file or directory.
W1016 19:38:09.280] 2019/10/16 19:38:09 process.go:155: Step 'bash -c hack/log-dump.sh /workspace/_artifacts' finished in 30.606132708s
W1016 19:38:09.281] 2019/10/16 19:38:09 azure.go:906: Deleting resource group: kubetest-4829425a-f046-11e9-97ea-0242873e7a00.
W1016 19:49:19.954] 2019/10/16 19:49:19 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml.
W1016 19:49:19.954] 2019/10/16 19:49:19 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
W1016 19:49:20.102] 2019/10/16 19:49:20 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 148.137187ms
W1016 19:49:20.102] 2019/10/16 19:49:20 main.go:319: Something went wrong: encountered 1 errors: [error during bash -c hack/log-dump.sh /workspace/_artifacts: exit status 255]
W1016 19:49:20.104] Traceback (most recent call last):
W1016 19:49:20.104]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module>
W1016 19:49:20.105]     main(parse_args())
W1016 19:49:20.105]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main
W1016 19:49:20.105]     mode.start(runner_args)
W1016 19:49:20.105]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start
W1016 19:49:20.105]     check_env(env, self.command, *args)
W1016 19:49:20.105]   File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env
W1016 19:49:20.105]     subprocess.check_call(cmd, env=env)
W1016 19:49:20.106]   File "/usr/lib/python2.7/subprocess.py", line 186, in check_call
W1016 19:49:20.106]     raise CalledProcessError(retcode, cmd)
W1016 19:49:20.106] 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.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz', '--timeout=420m')' returned non-zero exit status 1
E1016 19:49:20.112] Command failed
I1016 19:49:20.112] process 689 exited with code 1 after 55.6m
E1016 19:49:20.112] FAIL: chewong-e2e-ccm
I1016 19:49:20.112] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W1016 19:49:20.960] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com]
I1016 19:49:20.990] process 2759 exited with code 0 after 0.0m
I1016 19:49:20.990] Call:  gcloud config get-value account
I1016 19:49:21.232] process 2771 exited with code 0 after 0.0m
I1016 19:49:21.233] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com
I1016 19:49:21.233] Upload result and artifacts...
I1016 19:49:21.233] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128
I1016 19:49:21.233] Call:  gsutil ls gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128/artifacts
W1016 19:49:22.404] CommandException: One or more URLs matched no objects.
E1016 19:49:22.483] Command failed
I1016 19:49:22.483] process 2783 exited with code 1 after 0.0m
W1016 19:49:22.483] Remote dir gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128/artifacts not exist yet
I1016 19:49:22.484] 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/1184542576745648128/artifacts
I1016 19:49:24.050] process 2925 exited with code 0 after 0.0m
I1016 19:49:24.053] Call:  git rev-parse HEAD
I1016 19:49:24.057] process 3452 exited with code 0 after 0.0m
I1016 19:49:24.057] Call:  git rev-parse HEAD
I1016 19:49:24.061] process 3453 exited with code 0 after 0.0m
I1016 19:49:24.061] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1016 19:49:25.045] process 3454 exited with code 0 after 0.0m
I1016 19:49:25.046] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json#1571250026235893'
I1016 19:49:26.269] process 3596 exited with code 0 after 0.0m
I1016 19:49:26.270] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571250026235893 cp /tmp/gsutil_IK5QyH gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json
I1016 19:49:27.560] process 3740 exited with code 0 after 0.0m
I1016 19:49:27.560] Call:  gsutil stat gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1016 19:49:28.510] process 3918 exited with code 0 after 0.0m
I1016 19:49:28.510] Call:  gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json#1571250030003448'
I1016 19:49:29.803] process 4060 exited with code 0 after 0.0m
I1016 19:49:29.804] Call:  gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571250030003448 cp /tmp/gsutil_FMT5mo gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json
I1016 19:49:31.227] process 4204 exited with code 0 after 0.0m
I1016 19:49:31.228] Call:  gsutil -q -h Content-Type:application/json cp /tmp/gsutil_ht9uGc gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1184542576745648128/finished.json
I1016 19:49:32.619] process 4382 exited with code 0 after 0.0m
I1016 19:49:32.619] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_AQvUhq gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/latest-build.txt
I1016 19:49:33.943] process 4560 exited with code 0 after 0.0m
I1016 19:49:33.943] Call:  gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_78r_TK gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/latest-build.txt
I1016 19:49:35.222] process 4738 exited with code 0 after 0.0m