W1021 21:07:25.868] ************************************************************************** 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 ************************************************************************** I1021 21:07:25.869] 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:5dd5805d1e39f8239e6d7acb8db36ad0e30e78a0 --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 --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.42.0/aks-engine-v0.42.0-linux-amd64.tar.gz --timeout=420m I1021 21:07:25.869] Bootstrap chewong-e2e-ccm... I1021 21:07:25.873] Builder: b310356f-f446-11e9-918b-16773c0c7aed I1021 21:07:25.874] Image: chewong/kubekins-e2e:v20191018-test-1 I1021 21:07:25.874] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560 I1021 21:07:25.874] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1021 21:07:26.395] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1021 21:07:26.427] process 217 exited with code 0 after 0.0m I1021 21:07:26.427] Call: gcloud config get-value account I1021 21:07:26.664] process 229 exited with code 0 after 0.0m I1021 21:07:26.665] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1021 21:07:26.665] Root: /go/src I1021 21:07:26.665] cd to /go/src I1021 21:07:26.665] Checkout: /go/src/k8s.io/kubernetes release-1.16 to /go/src/k8s.io/kubernetes I1021 21:07:26.666] Call: git init k8s.io/kubernetes I1021 21:07:26.669] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/ I1021 21:07:26.670] process 241 exited with code 0 after 0.0m I1021 21:07:26.670] Call: git config --local user.name 'K8S Bootstrap' I1021 21:07:26.672] process 242 exited with code 0 after 0.0m I1021 21:07:26.672] Call: git config --local user.email k8s_bootstrap@localhost I1021 21:07:26.675] process 243 exited with code 0 after 0.0m I1021 21:07:26.675] Call: git fetch --quiet --tags https://github.com/kubernetes/kubernetes release-1.16 I1021 21:08:19.243] process 244 exited with code 0 after 0.9m I1021 21:08:19.243] Call: git checkout -B test FETCH_HEAD W1021 21:08:21.420] Switched to a new branch 'test' I1021 21:08:21.431] process 256 exited with code 0 after 0.0m I1021 21:08:21.432] Call: git show -s --format=format:%ct HEAD I1021 21:08:21.437] process 257 exited with code 0 after 0.0m I1021 21:08:21.437] Checkout: /go/src/k8s.io/cloud-provider-azure master:c470e6f36d76e5a565478fcba22118c06bc1548f,248:5dd5805d1e39f8239e6d7acb8db36ad0e30e78a0 to /go/src/k8s.io/cloud-provider-azure I1021 21:08:21.437] Call: git init k8s.io/cloud-provider-azure I1021 21:08:21.441] Initialized empty Git repository in /go/src/k8s.io/cloud-provider-azure/.git/ I1021 21:08:21.441] process 258 exited with code 0 after 0.0m I1021 21:08:21.441] Call: git config --local user.name 'K8S Bootstrap' I1021 21:08:21.443] process 259 exited with code 0 after 0.0m I1021 21:08:21.444] Call: git config --local user.email k8s_bootstrap@localhost I1021 21:08:21.446] process 260 exited with code 0 after 0.0m I1021 21:08:21.446] Call: git fetch --quiet --tags https://github.com/kubernetes/cloud-provider-azure master +refs/pull/248/head:refs/pr/248 I1021 21:08:22.878] process 261 exited with code 0 after 0.0m I1021 21:08:22.879] Call: git checkout -B test c470e6f36d76e5a565478fcba22118c06bc1548f W1021 21:08:23.308] Switched to a new branch 'test' I1021 21:08:23.311] process 273 exited with code 0 after 0.0m I1021 21:08:23.312] Call: git show -s --format=format:%ct HEAD I1021 21:08:23.314] process 274 exited with code 0 after 0.0m I1021 21:08:23.315] Call: git merge --no-ff -m 'Merge +refs/pull/248/head:refs/pr/248' 5dd5805d1e39f8239e6d7acb8db36ad0e30e78a0 I1021 21:08:23.689] Merge made by the 'recursive' strategy. I1021 21:08:23.691] hack/log-dump/log-dump-daemonset.yaml | 52 +++++++++++++ I1021 21:08:23.691] hack/log-dump/log-dump.sh | 140 ++++++++++++++++++++++++++++++++++ I1021 21:08:23.691] 2 files changed, 192 insertions(+) I1021 21:08:23.692] create mode 100644 hack/log-dump/log-dump-daemonset.yaml I1021 21:08:23.692] create mode 100755 hack/log-dump/log-dump.sh I1021 21:08:23.692] process 275 exited with code 0 after 0.0m I1021 21:08:23.692] Configure environment... I1021 21:08:23.692] Call: git show -s --format=format:%ct HEAD I1021 21:08:23.698] process 277 exited with code 0 after 0.0m I1021 21:08:23.698] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1021 21:08:24.333] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1021 21:08:24.444] process 278 exited with code 0 after 0.0m I1021 21:08:24.444] Call: gcloud config get-value account I1021 21:08:24.700] process 290 exited with code 0 after 0.0m I1021 21:08:24.700] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1021 21:08:24.700] 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 ' I1021 21:08:25.037] process 302 exited with code 0 after 0.0m I1021 21:08:25.037] Start 1186388489969602560 at v1.16.3-beta.0.16+1cd381987d44f1... I1021 21:08:25.039] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_tPxeiK gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560/started.json I1021 21:08:26.601] process 335 exited with code 0 after 0.0m I1021 21:08:26.602] 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/1186388489969602560' cp /tmp/gsutil_6tVpyI gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/1186388489969602560.txt I1021 21:08:28.065] process 513 exited with code 0 after 0.0m I1021 21:08:28.066] Call: /workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --provider=skeleton --ginkgo-parallel=30 --test-ccm=True --acsengine-agentpoolcount=1 '--acsengine-admin-username=$AZURE_SSH_USER' --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.42.0/aks-engine-v0.42.0-linux-amd64.tar.gz --timeout=420m W1021 21:08:28.105] starts with local mode W1021 21:08:28.106] Environment: W1021 21:08:28.106] ARTIFACTS=/workspace/_artifacts W1021 21:08:28.106] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa W1021 21:08:28.106] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub W1021 21:08:28.106] AZURE_CREDENTIALS=/etc/azure-cred/credentials W1021 21:08:28.106] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub W1021 21:08:28.107] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer W1021 21:08:28.107] BAZEL_REMOTE_CACHE_ENABLED=false W1021 21:08:28.107] BAZEL_VERSION=0.23.2 W1021 21:08:28.107] BOOTSTRAP_MIGRATION=yes W1021 21:08:28.107] BUILD_ID=1186388489969602560 W1021 21:08:28.108] BUILD_NUMBER=1186388489969602560 W1021 21:08:28.108] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true W1021 21:08:28.108] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud W1021 21:08:28.108] CLOUDSDK_CORE_DISABLE_PROMPTS=1 W1021 21:08:28.108] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false W1021 21:08:28.108] CLOUD_CONFIG=random W1021 21:08:28.109] DECK_PORT=tcp://10.0.160.83:80 W1021 21:08:28.109] DECK_PORT_80_TCP=tcp://10.0.160.83:80 W1021 21:08:28.109] DECK_PORT_80_TCP_ADDR=10.0.160.83 W1021 21:08:28.109] DECK_PORT_80_TCP_PORT=80 W1021 21:08:28.109] DECK_PORT_80_TCP_PROTO=tcp W1021 21:08:28.109] DECK_SERVICE_HOST=10.0.160.83 W1021 21:08:28.110] DECK_SERVICE_PORT=80 W1021 21:08:28.110] DOCKER_IN_DOCKER_ENABLED=true W1021 21:08:28.110] DOCKER_IN_DOCKER_IPV6_ENABLED=false W1021 21:08:28.110] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560/artifacts W1021 21:08:28.111] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json W1021 21:08:28.111] GOPATH=/go W1021 21:08:28.111] GO_TARBALL=go1.12.10.linux-amd64.tar.gz W1021 21:08:28.111] HOME=/workspace W1021 21:08:28.111] HOOK_PORT=tcp://10.0.144.133:8888 W1021 21:08:28.111] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888 W1021 21:08:28.112] HOOK_PORT_8888_TCP_ADDR=10.0.144.133 W1021 21:08:28.112] HOOK_PORT_8888_TCP_PORT=8888 W1021 21:08:28.112] HOOK_PORT_8888_TCP_PROTO=tcp W1021 21:08:28.112] HOOK_SERVICE_HOST=10.0.144.133 W1021 21:08:28.112] HOOK_SERVICE_PORT=8888 W1021 21:08:28.112] HOSTNAME=b310356f-f446-11e9-918b-16773c0c7aed W1021 21:08:28.113] IMAGE=chewong/kubekins-e2e:v20191018-test-1 W1021 21:08:28.113] INSTANCE_PREFIX=bootstrap-e2e W1021 21:08:28.113] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine W1021 21:08:28.113] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub W1021 21:08:28.113] JOB_NAME=chewong-e2e-ccm W1021 21:08:28.114] JOB_SPEC={"type":"presubmit","job":"chewong-e2e-ccm","buildid":"1186388489969602560","prowjobid":"b310356f-f446-11e9-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"b717be8269a4f381ab6c23e711e8924bc1f64c93","base_link":"https://github.com/Azure/kubernetes/commit/b717be8269a4f381ab6c23e711e8924bc1f64c93","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"}]}} W1021 21:08:28.114] JOB_TYPE=presubmit W1021 21:08:28.114] KUBERNETES_PORT=tcp://10.0.0.1:443 W1021 21:08:28.114] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443 W1021 21:08:28.114] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1 W1021 21:08:28.114] KUBERNETES_PORT_443_TCP_PORT=443 W1021 21:08:28.115] KUBERNETES_PORT_443_TCP_PROTO=tcp W1021 21:08:28.115] KUBERNETES_SERVICE_HOST=10.0.0.1 W1021 21:08:28.115] KUBERNETES_SERVICE_PORT=443 W1021 21:08:28.115] KUBERNETES_SERVICE_PORT_HTTPS=443 W1021 21:08:28.115] KUBETEST_IN_DOCKER=true W1021 21:08:28.115] KUBETEST_MANUAL_DUMP=y W1021 21:08:28.116] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e W1021 21:08:28.116] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e W1021 21:08:28.116] KUBE_VERBOSE=0 W1021 21:08:28.116] NODE_NAME=b310356f-f446-11e9-918b-16773c0c7aed W1021 21:08:28.116] 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 W1021 21:08:28.117] PROW_JOB_ID=b310356f-f446-11e9-918b-16773c0c7aed W1021 21:08:28.118] PULL_BASE_REF=master W1021 21:08:28.118] PULL_BASE_SHA=b717be8269a4f381ab6c23e711e8924bc1f64c93 W1021 21:08:28.118] PULL_NUMBER=113 W1021 21:08:28.118] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822 W1021 21:08:28.118] PULL_REFS=master:b717be8269a4f381ab6c23e711e8924bc1f64c93,113:879465972041635fd7bc8269da49153b67e63822 W1021 21:08:28.118] PWD=/workspace W1021 21:08:28.119] REGISTRY=k8sprowinternal.azurecr.io W1021 21:08:28.119] REPO_NAME=kubernetes W1021 21:08:28.119] REPO_OWNER=Azure W1021 21:08:28.119] SHLVL=2 W1021 21:08:28.119] SOURCE_DATE_EPOCH=1571647177 W1021 21:08:28.119] TERM=xterm W1021 21:08:28.119] TIDE_PORT=tcp://10.0.180.53:80 W1021 21:08:28.120] TIDE_PORT_80_TCP=tcp://10.0.180.53:80 W1021 21:08:28.120] TIDE_PORT_80_TCP_ADDR=10.0.180.53 W1021 21:08:28.120] TIDE_PORT_80_TCP_PORT=80 W1021 21:08:28.120] TIDE_PORT_80_TCP_PROTO=tcp W1021 21:08:28.120] TIDE_SERVICE_HOST=10.0.180.53 W1021 21:08:28.120] TIDE_SERVICE_PORT=80 W1021 21:08:28.120] WORKSPACE=/workspace W1021 21:08:28.120] _=./test-infra/jenkins/bootstrap.py W1021 21:08:28.121] Run: ('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--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=$AZURE_SSH_USER', '--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.42.0/aks-engine-v0.42.0-linux-amd64.tar.gz', '--timeout=420m') W1021 21:08:28.122] 2019/10/21 21:08:28 main.go:332: Limiting testing to 7h0m0s W1021 21:08:28.122] 2019/10/21 21:08:28 azure.go:232: Reading credentials file /etc/azure-cred/credentials W1021 21:08:28.122] 2019/10/21 21:08:28 azure.go:654: CWD /go/src/k8s.io/kubernetes W1021 21:08:28.122] 2019/10/21 21:08:28 azure.go:673: Attempting Docker login with azure cred. W1021 21:08:29.236] 2019/10/21 21:08:29 azure.go:682: Docker login success. W1021 21:08:29.237] 2019/10/21 21:08:29 azure.go:697: Building ccm. W1021 21:08:29.237] 2019/10/21 21:08:29 azure.go:699: projectPath /go/src/k8s.io/cloud-provider-azure W1021 21:08:29.237] 2019/10/21 21:08:29 process.go:153: Running: docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1186388489969602560-ed839856 . I1021 21:08:30.587] Sending build context to Docker daemon 67.16MB I1021 21:08:30.619] Step 1/7 : FROM golang:1.12.9-stretch AS build I1021 21:08:31.517] 1.12.9-stretch: Pulling from library/golang I1021 21:08:31.844] 092586df9206: Pulling fs layer I1021 21:08:31.845] ef599477fae0: Pulling fs layer I1021 21:08:31.845] 4530c6472b5d: Pulling fs layer I1021 21:08:31.845] d34d61487075: Pulling fs layer I1021 21:08:31.845] 89c6ec31b9e9: Pulling fs layer I1021 21:08:31.845] e37857ebcafa: Pulling fs layer I1021 21:08:31.845] b0e29f6c7f0a: Pulling fs layer I1021 21:08:31.846] d34d61487075: Waiting I1021 21:08:31.846] b0e29f6c7f0a: Waiting I1021 21:08:31.846] e37857ebcafa: Waiting I1021 21:08:31.846] 89c6ec31b9e9: Waiting I1021 21:08:32.240] 4530c6472b5d: Verifying Checksum I1021 21:08:32.240] 4530c6472b5d: Download complete I1021 21:08:32.343] ef599477fae0: Verifying Checksum I1021 21:08:32.343] ef599477fae0: Download complete I1021 21:08:32.619] 092586df9206: Download complete I1021 21:08:33.195] d34d61487075: Verifying Checksum I1021 21:08:33.196] d34d61487075: Download complete I1021 21:08:33.441] 89c6ec31b9e9: Verifying Checksum I1021 21:08:33.442] 89c6ec31b9e9: Download complete I1021 21:08:33.556] b0e29f6c7f0a: Download complete I1021 21:08:34.296] e37857ebcafa: Verifying Checksum I1021 21:08:34.296] e37857ebcafa: Download complete I1021 21:08:35.802] 092586df9206: Pull complete I1021 21:08:36.574] ef599477fae0: Pull complete I1021 21:08:36.934] 4530c6472b5d: Pull complete I1021 21:08:40.556] d34d61487075: Pull complete I1021 21:08:54.989] 89c6ec31b9e9: Pull complete I1021 21:09:05.071] e37857ebcafa: Pull complete I1021 21:09:05.245] b0e29f6c7f0a: Pull complete I1021 21:09:05.268] Digest: sha256:76b52857546f070cc3ac499accb27b8c411b10ff6d45c0b1da2a8aab7b61fe29 I1021 21:09:05.288] Status: Downloaded newer image for golang:1.12.9-stretch I1021 21:09:05.288] ---> 2c4a601e5da9 I1021 21:09:05.289] Step 2/7 : WORKDIR /go/src/k8s.io/cloud-provider-azure I1021 21:09:07.170] ---> Running in cc04e20f071e I1021 21:09:09.112] Removing intermediate container cc04e20f071e I1021 21:09:09.113] ---> fd6728808833 I1021 21:09:09.113] Step 3/7 : COPY . . I1021 21:09:15.605] ---> 36914164af97 I1021 21:09:15.605] Step 4/7 : RUN make I1021 21:09:15.935] ---> Running in 599ac0eb2ad9 I1021 21:09:16.834] hack/pkg-config.sh > .pkg_config I1021 21:09:16.856] go build -o bin/azure-cloud-controller-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-11-gb6a51653d -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=b6a51653dac907e44dbc7f4d147fa6b8cd50faab -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-21T21:09:16Z' ./cmd/cloud-controller-manager I1021 21:10:09.520] go build -o bin/azure-cloud-node-manager -ldflags '-s -w -X k8s.io/cloud-provider-azure/pkg/version.gitVersion=v0.3.0-11-gb6a51653d -X k8s.io/cloud-provider-azure/pkg/version.gitCommit=b6a51653dac907e44dbc7f4d147fa6b8cd50faab -X k8s.io/cloud-provider-azure/pkg/version.buildDate=2019-10-21T21:09:16Z' ./cmd/cloud-node-manager I1021 21:10:35.708] Removing intermediate container 599ac0eb2ad9 I1021 21:10:35.708] ---> be98fac57930 I1021 21:10:35.708] Step 5/7 : FROM k8s.gcr.io/debian-base:v1.0.0 I1021 21:10:36.005] v1.0.0: Pulling from debian-base I1021 21:10:36.177] 39fafc05754f: Pulling fs layer I1021 21:10:36.575] 39fafc05754f: Verifying Checksum I1021 21:10:36.575] 39fafc05754f: Download complete I1021 21:10:41.173] 39fafc05754f: Pull complete I1021 21:10:41.204] Digest: sha256:3801f944c765dc1b54900826ca67b1380bb8c73b9caf4a2a27ce613b3ba3e742 I1021 21:10:41.222] Status: Downloaded newer image for k8s.gcr.io/debian-base:v1.0.0 I1021 21:10:41.223] ---> 204e96332c91 I1021 21:10:41.223] Step 6/7 : COPY --from=build /go/src/k8s.io/cloud-provider-azure/bin/azure-cloud-controller-manager /usr/local/bin I1021 21:10:44.343] ---> 51209dda4a7c I1021 21:10:44.343] Step 7/7 : RUN ln -s /usr/local/bin/azure-cloud-controller-manager /usr/local/bin/cloud-controller-manager I1021 21:10:44.491] ---> Running in 7d2bdf71b9d1 I1021 21:10:46.059] Removing intermediate container 7d2bdf71b9d1 I1021 21:10:46.060] ---> cf7a75d0af8f I1021 21:10:46.173] Successfully built cf7a75d0af8f I1021 21:10:46.308] Successfully tagged k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1186388489969602560-ed839856 W1021 21:10:46.408] 2019/10/21 21:10:46 process.go:155: Step 'docker build -t k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1186388489969602560-ed839856 .' finished in 2m17.074363325s W1021 21:10:46.409] 2019/10/21 21:10:46 process.go:153: Running: docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1186388489969602560-ed839856 W1021 21:10:52.253] 2019/10/21 21:10:52 process.go:155: Step 'docker push k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1186388489969602560-ed839856' finished in 5.941882479s W1021 21:10:52.253] 2019/10/21 21:10:52 azure.go:686: Docker logout. W1021 21:10:52.323] 2019/10/21 21:10:52 azure.go:716: Custom cloud controller manager URL: k8sprowinternal.azurecr.io/azure-cloud-controller-manager:1186388489969602560-ed839856 . W1021 21:10:52.323] 2019/10/21 21:10:52 azure.go:654: CWD /go/src/k8s.io/kubernetes W1021 21:10:52.324] 2019/10/21 21:10:52 azure.go:673: Attempting Docker login with azure cred. W1021 21:10:52.476] 2019/10/21 21:10:52 azure.go:682: Docker login success. W1021 21:10:52.477] 2019/10/21 21:10:52 azure.go:726: Building hyperkube. W1021 21:10:52.477] 2019/10/21 21:10:52 process.go:153: Running: make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube W1021 21:14:25.016] 2019/10/21 21:14:25 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes WHAT=cmd/hyperkube' finished in 3m32.539077462s W1021 21:14:25.016] 2019/10/21 21:14:25 azure.go:733: Pushing hyperkube. W1021 21:14:25.016] 2019/10/21 21:14:25 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 I1021 21:14:25.117] make: Entering directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube' I1021 21:14:25.117] cp -r ./* /tmp/hyperkubeC5p94B I1021 21:14:25.117] cp /go/src/k8s.io/kubernetes/_output/bin/hyperkube /tmp/hyperkubeC5p94B I1021 21:14:25.201] chmod a+rx /tmp/hyperkubeC5p94B/hyperkube I1021 21:14:25.202] cd /tmp/hyperkubeC5p94B && sed -i.back "s|BASEIMAGE|k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1|g" Dockerfile I1021 21:14:25.208] docker build --pull -t k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1186388489969602560-4376ec88 /tmp/hyperkubeC5p94B I1021 21:14:26.504] Sending build context to Docker daemon 212.1MB I1021 21:14:26.527] Step 1/2 : FROM k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1 I1021 21:14:26.822] 0.12.1: Pulling from debian-hyperkube-base-amd64 I1021 21:14:26.822] 346aee5ea5bc: Pulling fs layer I1021 21:14:26.823] 9c47fde751af: Pulling fs layer I1021 21:14:26.823] be2693a52daf: Pulling fs layer I1021 21:14:26.823] 6b69eb11d043: Pulling fs layer I1021 21:14:26.823] 0abeb1500767: Pulling fs layer I1021 21:14:26.823] 4062d80041b7: Pulling fs layer I1021 21:14:26.823] 23b6daf06fc2: Pulling fs layer I1021 21:14:26.823] 6b69eb11d043: Waiting I1021 21:14:26.824] 0abeb1500767: Waiting I1021 21:14:26.824] 4062d80041b7: Waiting I1021 21:14:26.824] 23b6daf06fc2: Waiting I1021 21:14:26.957] 9c47fde751af: Verifying Checksum I1021 21:14:26.957] 9c47fde751af: Download complete I1021 21:14:26.985] be2693a52daf: Verifying Checksum I1021 21:14:26.985] be2693a52daf: Download complete I1021 21:14:27.095] 6b69eb11d043: Verifying Checksum I1021 21:14:27.095] 6b69eb11d043: Download complete I1021 21:14:27.123] 0abeb1500767: Verifying Checksum I1021 21:14:27.123] 0abeb1500767: Download complete I1021 21:14:27.270] 346aee5ea5bc: Verifying Checksum I1021 21:14:27.270] 346aee5ea5bc: Download complete I1021 21:14:27.827] 23b6daf06fc2: Verifying Checksum I1021 21:14:27.827] 23b6daf06fc2: Download complete I1021 21:14:28.343] 4062d80041b7: Verifying Checksum I1021 21:14:28.344] 4062d80041b7: Download complete I1021 21:14:33.078] 346aee5ea5bc: Pull complete I1021 21:14:33.278] 9c47fde751af: Pull complete I1021 21:14:33.477] be2693a52daf: Pull complete I1021 21:14:33.624] 6b69eb11d043: Pull complete I1021 21:14:33.785] 0abeb1500767: Pull complete I1021 21:14:42.487] 4062d80041b7: Pull complete I1021 21:14:43.814] 23b6daf06fc2: Pull complete I1021 21:14:43.836] Digest: sha256:5d4ea2fb5fbe9a9a9da74f67cf2faefc881968bc39f2ac5d62d9167e575812a1 I1021 21:14:43.854] Status: Downloaded newer image for k8s.gcr.io/debian-hyperkube-base-amd64:0.12.1 I1021 21:14:43.854] ---> a46476511725 I1021 21:14:43.855] Step 2/2 : COPY hyperkube /hyperkube I1021 21:15:08.885] ---> 65b9a94e59ad I1021 21:15:08.912] Successfully built 65b9a94e59ad I1021 21:15:08.986] Successfully tagged k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1186388489969602560-4376ec88 I1021 21:15:08.994] rm -rf "/tmp/hyperkubeC5p94B" I1021 21:15:09.050] docker push k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1186388489969602560-4376ec88 I1021 21:15:09.170] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube-amd64] I1021 21:15:09.209] 943f484805f4: Preparing I1021 21:15:09.226] 39b3ac6d96e9: Preparing I1021 21:15:09.226] 7bbae4dddb88: Preparing I1021 21:15:09.226] a00defcfe869: Preparing I1021 21:15:09.227] 2ab0ae805c74: Preparing I1021 21:15:09.227] 43a8fe7d2382: Preparing I1021 21:15:09.227] 3f6a6f542637: Preparing I1021 21:15:09.228] 5ba3be777c2d: Preparing I1021 21:15:09.228] 43a8fe7d2382: Waiting I1021 21:15:09.230] 3f6a6f542637: Waiting I1021 21:15:09.230] 5ba3be777c2d: Waiting I1021 21:15:09.510] 7bbae4dddb88: Layer already exists I1021 21:15:09.536] 2ab0ae805c74: Layer already exists I1021 21:15:09.582] 39b3ac6d96e9: Layer already exists I1021 21:15:09.594] a00defcfe869: Layer already exists I1021 21:15:09.669] 3f6a6f542637: Layer already exists I1021 21:15:09.697] 43a8fe7d2382: Layer already exists I1021 21:15:09.718] 5ba3be777c2d: Layer already exists I1021 21:15:28.444] 943f484805f4: Pushed I1021 21:15:29.252] azure-e2e-1186388489969602560-4376ec88: digest: sha256:8a7b6667bf009c0c43a17507419f7264ea7ea2f402edc353dfcefcc426d459de size: 1998 I1021 21:15:29.277] docker rmi k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1186388489969602560-4376ec88 2>/dev/null || true I1021 21:15:29.401] docker tag k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1186388489969602560-4376ec88 k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1186388489969602560-4376ec88 I1021 21:15:29.522] docker push k8sprowinternal.azurecr.io/hyperkube:azure-e2e-1186388489969602560-4376ec88 I1021 21:15:29.698] The push refers to repository [k8sprowinternal.azurecr.io/hyperkube] I1021 21:15:29.731] 943f484805f4: Preparing I1021 21:15:29.732] 39b3ac6d96e9: Preparing I1021 21:15:29.732] 7bbae4dddb88: Preparing I1021 21:15:29.732] a00defcfe869: Preparing I1021 21:15:29.733] 2ab0ae805c74: Preparing I1021 21:15:29.733] 43a8fe7d2382: Preparing I1021 21:15:29.734] 3f6a6f542637: Preparing I1021 21:15:29.734] 5ba3be777c2d: Preparing I1021 21:15:29.734] 43a8fe7d2382: Waiting I1021 21:15:29.735] 3f6a6f542637: Waiting I1021 21:15:29.735] 5ba3be777c2d: Waiting I1021 21:15:29.904] 2ab0ae805c74: Layer already exists I1021 21:15:29.958] a00defcfe869: Layer already exists I1021 21:15:29.975] 7bbae4dddb88: Layer already exists I1021 21:15:29.994] 39b3ac6d96e9: Layer already exists I1021 21:15:30.022] 43a8fe7d2382: Layer already exists I1021 21:15:30.042] 943f484805f4: Mounted from hyperkube-amd64 I1021 21:15:30.066] 3f6a6f542637: Layer already exists I1021 21:15:30.102] 5ba3be777c2d: Layer already exists I1021 21:15:30.742] azure-e2e-1186388489969602560-4376ec88: digest: sha256:8a7b6667bf009c0c43a17507419f7264ea7ea2f402edc353dfcefcc426d459de size: 1998 I1021 21:15:30.770] make: Leaving directory '/go/src/k8s.io/kubernetes/cluster/images/hyperkube' W1021 21:15:30.874] 2019/10/21 21:15:30 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 1m5.755177566s W1021 21:15:30.874] 2019/10/21 21:15:30 azure.go:686: Docker logout. W1021 21:15:30.946] 2019/10/21 21:15:30 azure.go:744: Custom hyperkube URL: k8sprowinternal.azurecr.io/hyperkube-amd64:azure-e2e-1186388489969602560-4376ec88 . W1021 21:15:30.946] 2019/10/21 21:15:30 azure.go:787: downloading /workspace/aks146026292/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json. W1021 21:15:30.946] 2019/10/21 21:15:30 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json W1021 21:15:31.366] 2019/10/21 21:15:31 azure.go:529: downloading /workspace/aks-engine.tar.gz from https://github.com/Azure/aks-engine/releases/download/v0.42.0/aks-engine-v0.42.0-linux-amd64.tar.gz. W1021 21:15:31.366] 2019/10/21 21:15:31 util.go:42: curl https://github.com/Azure/aks-engine/releases/download/v0.42.0/aks-engine-v0.42.0-linux-amd64.tar.gz W1021 21:15:32.658] 2019/10/21 21:15:32 azure.go:556: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes . W1021 21:15:32.659] 2019/10/21 21:15:32 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1 W1021 21:15:32.866] 2019/10/21 21:15:32 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 207.539511ms W1021 21:15:32.867] 2019/10/21 21:15:32 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks146026292/kubernetes.json --output-directory /workspace/aks146026292 I1021 21:15:33.119] INFO[0000] Generating assets into /workspace/aks146026292... W1021 21:15:59.570] 2019/10/21 21:15:59 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks146026292/kubernetes.json --output-directory /workspace/aks146026292' finished in 26.701370325s W1021 21:15:59.574] 2019/10/21 21:15:59 azure.go:627: Setting kubeconfig env variable: kubeconfig path: /workspace/aks146026292/kubeconfig/kubeconfig.eastus2.json. W1021 21:15:59.574] 2019/10/21 21:15:59 azure.go:629: Creating resource group: kubetest-ed837ed2-f446-11e9-bf80-02424c4e6e30. W1021 21:15:59.574] 2019/10/21 21:15:59 azure.go:631: Creating Azure resource group: kubetest-ed837ed2-f446-11e9-bf80-02424c4e6e30 for cluster deployment. W1021 21:16:01.671] 2019/10/21 21:16:01 azure.go:636: Validating deployment ARM templates. W1021 21:16:03.564] 2019/10/21 21:16:03 azure.go:642: Deploying cluster kubetest-ed837ed2-f446-11e9-bf80-02424c4e6e30 in resource group kubetest-ed837ed2-f446-11e9-bf80-02424c4e6e30. W1021 21:19:08.980] 2019/10/21 21:19:08 process.go:153: Running: bash -c sleep 60 && ./hack/log-dump.sh W1021 21:20:08.984] bash: ./hack/log-dump.sh: No such file or directory W1021 21:20:08.985] 2019/10/21 21:20:08 process.go:155: Step 'bash -c sleep 60 && ./hack/log-dump.sh' finished in 1m0.00417175s W1021 21:20:08.985] 2019/10/21 21:20:08 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W1021 21:20:08.985] 2019/10/21 21:20:08 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W1021 21:20:09.141] 2019/10/21 21:20:09 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 156.432017ms W1021 21:20:09.142] 2019/10/21 21:20:09 main.go:319: Something went wrong: starting e2e cluster: error creating cluster: cannot deploy: cannot get the create deployment future response: Code="DeploymentFailed" Message="At least one resource deployment operation failed. Please list deployment operations for details. Please see https://aka.ms/arm-debug for usage details." Details=[{"code":"BadRequest","message":"{\r\n \"error\": {\r\n \"code\": \"InvalidParameter\",\r\n \"message\": \"The value of parameter linuxConfiguration.ssh.publicKeys.path is invalid.\",\r\n \"target\": \"linuxConfiguration.ssh.publicKeys.path\"\r\n }\r\n}"},{"code":"BadRequest","message":"{\r\n \"error\": {\r\n \"code\": \"InvalidParameter\",\r\n \"message\": \"The value of parameter linuxConfiguration.ssh.publicKeys.path is invalid.\",\r\n \"target\": \"linuxConfiguration.ssh.publicKeys.path\"\r\n }\r\n}"}] W1021 21:20:09.143] Traceback (most recent call last): W1021 21:20:09.143] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in W1021 21:20:09.143] main(parse_args()) W1021 21:20:09.143] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W1021 21:20:09.144] mode.start(runner_args) W1021 21:20:09.144] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W1021 21:20:09.144] check_env(env, self.command, *args) W1021 21:20:09.144] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W1021 21:20:09.144] subprocess.check_call(cmd, env=env) W1021 21:20:09.145] File "/usr/lib/python2.7/subprocess.py", line 186, in check_call W1021 21:20:09.145] raise CalledProcessError(retcode, cmd) W1021 21:20:09.146] subprocess.CalledProcessError: Command '('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--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=$AZURE_SSH_USER', '--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.42.0/aks-engine-v0.42.0-linux-amd64.tar.gz', '--timeout=420m')' returned non-zero exit status 1 E1021 21:20:09.150] Command failed I1021 21:20:09.150] process 691 exited with code 1 after 11.7m E1021 21:20:09.151] FAIL: chewong-e2e-ccm I1021 21:20:09.151] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1021 21:20:09.738] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1021 21:20:09.769] process 29159 exited with code 0 after 0.0m I1021 21:20:09.769] Call: gcloud config get-value account I1021 21:20:10.007] process 29171 exited with code 0 after 0.0m I1021 21:20:10.007] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1021 21:20:10.007] Upload result and artifacts... I1021 21:20:10.007] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560 I1021 21:20:10.008] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560/artifacts W1021 21:20:10.965] CommandException: One or more URLs matched no objects. E1021 21:20:11.044] Command failed I1021 21:20:11.044] process 29183 exited with code 1 after 0.0m W1021 21:20:11.045] Remote dir gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560/artifacts not exist yet I1021 21:20:11.045] 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/1186388489969602560/artifacts I1021 21:20:12.680] process 29325 exited with code 0 after 0.0m I1021 21:20:12.683] Call: git rev-parse HEAD I1021 21:20:12.686] process 29849 exited with code 0 after 0.0m I1021 21:20:12.686] Call: git rev-parse HEAD I1021 21:20:12.688] process 29850 exited with code 0 after 0.0m I1021 21:20:12.689] Call: gsutil stat gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json I1021 21:20:13.648] process 29851 exited with code 0 after 0.0m I1021 21:20:13.648] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json#1571433864256200' I1021 21:20:14.857] process 29993 exited with code 0 after 0.0m I1021 21:20:14.858] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571433864256200 cp /tmp/gsutil_s_rhS8 gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/jobResultsCache.json I1021 21:20:16.281] process 30137 exited with code 0 after 0.0m I1021 21:20:16.281] Call: gsutil stat gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json I1021 21:20:17.263] process 30315 exited with code 0 after 0.0m I1021 21:20:17.264] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json#1571433868216450' I1021 21:20:18.602] process 30457 exited with code 0 after 0.0m I1021 21:20:18.604] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1571433868216450 cp /tmp/gsutil_WJovwF gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/jobResultsCache.json I1021 21:20:19.907] process 30601 exited with code 0 after 0.0m I1021 21:20:19.908] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_l5i3de gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/1186388489969602560/finished.json I1021 21:20:21.329] process 30779 exited with code 0 after 0.0m I1021 21:20:21.330] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_Vcw46d gs://kubernetes-upstream/pr-logs/directory/chewong-e2e-ccm/latest-build.txt I1021 21:20:22.663] process 30957 exited with code 0 after 0.0m I1021 21:20:22.664] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_JQJRH1 gs://kubernetes-upstream/pr-logs/pull/cloud-provider-azure/248/chewong-e2e-ccm/latest-build.txt I1021 21:20:24.064] process 31135 exited with code 0 after 0.0m