W0927 05:49:56.151] ************************************************************************** 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 ************************************************************************** I0927 05:49:56.152] Args: --job=pull-azurefile-csi-driver-e2e --service-account=/etc/service-account/service-account.json --upload=gs://kubernetes-jenkins/logs --job=pull-azurefile-csi-driver-e2e --root=/go/src --service-account=/etc/service-account/service-account.json --repo=k8s.io/kubernetes --repo=github.com/kubernetes-sigs/azurefile-csi-driver=master:daea67167aecc01a8bfa2b24f33c4a08998cdc74,120:54f98c722b41e3e5fd2f6581defa0c4fafa962f2 --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=1 --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-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 --test-azure-file-csi-driver=True I0927 05:49:56.152] Bootstrap pull-azurefile-csi-driver-e2e... I0927 05:49:56.155] Builder: 95610b88-e0ea-11e9-918b-16773c0c7aed I0927 05:49:56.155] Image: chewong/kubekins-e2e:v20190926-7484d81-azurefile-csi-driver-config I0927 05:49:56.155] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424 I0927 05:49:56.156] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W0927 05:49:56.660] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I0927 05:49:56.689] process 215 exited with code 0 after 0.0m I0927 05:49:56.689] Call: gcloud config get-value account I0927 05:49:56.925] process 227 exited with code 0 after 0.0m I0927 05:49:56.925] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I0927 05:49:56.925] Root: /go/src I0927 05:49:56.925] cd to /go/src I0927 05:49:56.926] Checkout: /go/src/k8s.io/kubernetes master to /go/src/k8s.io/kubernetes I0927 05:49:56.926] Call: git init k8s.io/kubernetes I0927 05:49:56.930] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/ I0927 05:49:56.930] process 239 exited with code 0 after 0.0m I0927 05:49:56.930] Call: git config --local user.name 'K8S Bootstrap' I0927 05:49:56.932] process 240 exited with code 0 after 0.0m I0927 05:49:56.933] Call: git config --local user.email k8s_bootstrap@localhost I0927 05:49:56.935] process 241 exited with code 0 after 0.0m I0927 05:49:56.935] Call: git fetch --quiet --tags https://github.com/kubernetes/kubernetes master I0927 05:50:46.834] process 242 exited with code 0 after 0.8m I0927 05:50:46.834] Call: git checkout -B test FETCH_HEAD W0927 05:50:49.206] Switched to a new branch 'test' I0927 05:50:49.214] process 254 exited with code 0 after 0.0m I0927 05:50:49.215] Call: git show -s --format=format:%ct HEAD I0927 05:50:49.219] process 255 exited with code 0 after 0.0m I0927 05:50:49.220] Checkout: /go/src/github.com/kubernetes-sigs/azurefile-csi-driver master:daea67167aecc01a8bfa2b24f33c4a08998cdc74,120:54f98c722b41e3e5fd2f6581defa0c4fafa962f2 to /go/src/github.com/kubernetes-sigs/azurefile-csi-driver I0927 05:50:49.220] Call: git init github.com/kubernetes-sigs/azurefile-csi-driver I0927 05:50:49.224] Initialized empty Git repository in /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/.git/ I0927 05:50:49.224] process 256 exited with code 0 after 0.0m I0927 05:50:49.224] Call: git config --local user.name 'K8S Bootstrap' I0927 05:50:49.226] process 257 exited with code 0 after 0.0m I0927 05:50:49.227] Call: git config --local user.email k8s_bootstrap@localhost I0927 05:50:49.229] process 258 exited with code 0 after 0.0m I0927 05:50:49.229] Call: git fetch --quiet --tags https://github.com/kubernetes-sigs/azurefile-csi-driver master +refs/pull/120/head:refs/pr/120 I0927 05:50:53.299] process 259 exited with code 0 after 0.1m I0927 05:50:53.299] Call: git checkout -B test daea67167aecc01a8bfa2b24f33c4a08998cdc74 W0927 05:50:53.792] Switched to a new branch 'test' I0927 05:50:53.794] process 271 exited with code 0 after 0.0m I0927 05:50:53.794] Call: git show -s --format=format:%ct HEAD I0927 05:50:53.804] process 272 exited with code 0 after 0.0m I0927 05:50:53.805] Call: git merge --no-ff -m 'Merge +refs/pull/120/head:refs/pr/120' 54f98c722b41e3e5fd2f6581defa0c4fafa962f2 I0927 05:50:54.137] Auto-merging test/utils/credentials/credentials_test.go I0927 05:50:54.137] Auto-merging test/utils/credentials/credentials.go I0927 05:50:54.138] Removing test/e2e/run-test.sh I0927 05:50:54.138] Removing hack/template/azure.json I0927 05:50:54.138] Removing .travis.yml I0927 05:50:54.138] Merge made by the 'recursive' strategy. I0927 05:50:54.141] .travis.yml | 30 -------- I0927 05:50:54.141] Makefile | 64 ++++++++++++----- I0927 05:50:54.141] hack/template/azure.json | 9 --- I0927 05:50:54.141] hack/verify-golint.sh | 7 +- I0927 05:50:54.141] test/e2e/README.md | 24 +++++-- I0927 05:50:54.142] test/e2e/dynamic_provisioning.go | 17 ----- I0927 05:50:54.142] test/e2e/pre_provisioning.go | 23 +------ I0927 05:50:54.142] test/e2e/run-test.sh | 31 --------- I0927 05:50:54.142] test/e2e/suite_test.go | 87 ++++++++++++++++++++++++ I0927 05:50:54.142] test/integration/integration_test.go | 20 +++++- I0927 05:50:54.142] test/integration/run-tests-all-clouds.sh | 4 +- I0927 05:50:54.142] test/sanity/run-test.sh | 3 +- I0927 05:50:54.143] test/sanity/run-tests-all-clouds.sh | 4 +- I0927 05:50:54.143] test/sanity/sanity_test.go | 17 ++--- I0927 05:50:54.143] test/{ => utils}/azure/azure_helpers.go | 0 I0927 05:50:54.143] test/{ => utils}/credentials/credentials.go | 65 ++++++++++++------ I0927 05:50:54.143] test/{ => utils}/credentials/credentials_test.go | 54 +++++++-------- I0927 05:50:54.143] test/utils/testutil/testutil.go | 8 +++ I0927 05:50:54.143] 18 files changed, 267 insertions(+), 200 deletions(-) I0927 05:50:54.144] delete mode 100644 .travis.yml I0927 05:50:54.144] delete mode 100644 hack/template/azure.json I0927 05:50:54.144] delete mode 100755 test/e2e/run-test.sh I0927 05:50:54.144] rename test/{ => utils}/azure/azure_helpers.go (100%) I0927 05:50:54.144] rename test/{ => utils}/credentials/credentials.go (68%) I0927 05:50:54.144] rename test/{ => utils}/credentials/credentials_test.go (77%) I0927 05:50:54.144] create mode 100644 test/utils/testutil/testutil.go I0927 05:50:54.144] process 273 exited with code 0 after 0.0m I0927 05:50:54.145] Configure environment... I0927 05:50:54.145] Call: git show -s --format=format:%ct HEAD I0927 05:50:54.150] process 275 exited with code 0 after 0.0m I0927 05:50:54.151] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W0927 05:50:54.755] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I0927 05:50:54.863] process 276 exited with code 0 after 0.0m I0927 05:50:54.863] Call: gcloud config get-value account I0927 05:50:55.099] process 288 exited with code 0 after 0.0m I0927 05:50:55.099] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I0927 05:50:55.099] 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 ' I0927 05:50:55.438] process 300 exited with code 0 after 0.0m I0927 05:50:55.438] Start 1177460284827111424 at v1.17.0-alpha.0.1869+d92a250636fadb... I0927 05:50:55.440] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_s7n4mF gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424/started.json I0927 05:50:57.153] process 333 exited with code 0 after 0.0m I0927 05:50:57.154] Call: gsutil -q -h Content-Type:text/plain -h 'x-goog-meta-link: gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424' cp /tmp/gsutil_m9hms8 gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/1177460284827111424.txt I0927 05:50:58.443] process 511 exited with code 0 after 0.0m I0927 05:50:58.444] 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=1 --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-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 --test-azure-file-csi-driver=True W0927 05:50:58.483] starts with local mode W0927 05:50:58.483] Environment: W0927 05:50:58.483] ARTIFACTS=/workspace/_artifacts W0927 05:50:58.483] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa W0927 05:50:58.483] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub W0927 05:50:58.483] AZURE_CREDENTIALS=/etc/azure-cred/credentials W0927 05:50:58.484] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub W0927 05:50:58.484] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer W0927 05:50:58.484] BAZEL_REMOTE_CACHE_ENABLED=false W0927 05:50:58.484] BAZEL_VERSION=0.23.2 W0927 05:50:58.484] BOOTSTRAP_MIGRATION=yes W0927 05:50:58.484] BUILD_ID=1177460284827111424 W0927 05:50:58.485] BUILD_NUMBER=1177460284827111424 W0927 05:50:58.485] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true W0927 05:50:58.485] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud W0927 05:50:58.485] CLOUDSDK_CORE_DISABLE_PROMPTS=1 W0927 05:50:58.485] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false W0927 05:50:58.485] CLOUD_CONFIG=random W0927 05:50:58.485] DECK_PORT=tcp://10.0.160.83:80 W0927 05:50:58.486] DECK_PORT_80_TCP=tcp://10.0.160.83:80 W0927 05:50:58.486] DECK_PORT_80_TCP_ADDR=10.0.160.83 W0927 05:50:58.486] DECK_PORT_80_TCP_PORT=80 W0927 05:50:58.486] DECK_PORT_80_TCP_PROTO=tcp W0927 05:50:58.486] DECK_SERVICE_HOST=10.0.160.83 W0927 05:50:58.486] DECK_SERVICE_PORT=80 W0927 05:50:58.487] DOCKER_IN_DOCKER_ENABLED=true W0927 05:50:58.487] DOCKER_IN_DOCKER_IPV6_ENABLED=false W0927 05:50:58.487] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424/artifacts W0927 05:50:58.487] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json W0927 05:50:58.487] GOPATH=/go W0927 05:50:58.487] GO_TARBALL=go1.12.1.linux-amd64.tar.gz W0927 05:50:58.487] HOME=/workspace W0927 05:50:58.488] HOOK_PORT=tcp://10.0.144.133:8888 W0927 05:50:58.488] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888 W0927 05:50:58.488] HOOK_PORT_8888_TCP_ADDR=10.0.144.133 W0927 05:50:58.488] HOOK_PORT_8888_TCP_PORT=8888 W0927 05:50:58.488] HOOK_PORT_8888_TCP_PROTO=tcp W0927 05:50:58.488] HOOK_SERVICE_HOST=10.0.144.133 W0927 05:50:58.489] HOOK_SERVICE_PORT=8888 W0927 05:50:58.489] HOSTNAME=95610b88-e0ea-11e9-918b-16773c0c7aed W0927 05:50:58.489] IMAGE=chewong/kubekins-e2e:v20190926-7484d81-azurefile-csi-driver-config W0927 05:50:58.489] INSTANCE_PREFIX=bootstrap-e2e W0927 05:50:58.489] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine W0927 05:50:58.489] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub W0927 05:50:58.490] JOB_NAME=pull-azurefile-csi-driver-e2e W0927 05:50:58.490] JOB_SPEC={"type":"presubmit","job":"pull-azurefile-csi-driver-e2e","buildid":"1177460284827111424","prowjobid":"95610b88-e0ea-11e9-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"d92a250636fadb2ce77bcadf832272c852ea9ed0","base_link":"https://github.com/Azure/kubernetes/commit/d92a250636fadb2ce77bcadf832272c852ea9ed0","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"}]}} W0927 05:50:58.490] JOB_TYPE=presubmit W0927 05:50:58.490] KUBERNETES_PORT=tcp://10.0.0.1:443 W0927 05:50:58.490] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443 W0927 05:50:58.490] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1 W0927 05:50:58.491] KUBERNETES_PORT_443_TCP_PORT=443 W0927 05:50:58.491] KUBERNETES_PORT_443_TCP_PROTO=tcp W0927 05:50:58.491] KUBERNETES_SERVICE_HOST=10.0.0.1 W0927 05:50:58.491] KUBERNETES_SERVICE_PORT=443 W0927 05:50:58.491] KUBERNETES_SERVICE_PORT_HTTPS=443 W0927 05:50:58.491] KUBETEST_IN_DOCKER=true W0927 05:50:58.491] KUBETEST_MANUAL_DUMP=y W0927 05:50:58.491] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e W0927 05:50:58.492] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e W0927 05:50:58.492] KUBE_VERBOSE=0 W0927 05:50:58.492] NODE_NAME=95610b88-e0ea-11e9-918b-16773c0c7aed W0927 05:50:58.492] 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 W0927 05:50:58.492] PROW_JOB_ID=95610b88-e0ea-11e9-918b-16773c0c7aed W0927 05:50:58.492] PULL_BASE_REF=master W0927 05:50:58.492] PULL_BASE_SHA=d92a250636fadb2ce77bcadf832272c852ea9ed0 W0927 05:50:58.493] PULL_NUMBER=113 W0927 05:50:58.493] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822 W0927 05:50:58.493] PULL_REFS=master:d92a250636fadb2ce77bcadf832272c852ea9ed0,113:879465972041635fd7bc8269da49153b67e63822 W0927 05:50:58.493] PWD=/workspace W0927 05:50:58.493] REGISTRY=k8sprowinternal.azurecr.io W0927 05:50:58.493] REPO_NAME=kubernetes W0927 05:50:58.493] REPO_OWNER=Azure W0927 05:50:58.493] SHLVL=2 W0927 05:50:58.494] SOURCE_DATE_EPOCH=1569551257 W0927 05:50:58.494] TERM=xterm W0927 05:50:58.494] TIDE_PORT=tcp://10.0.180.53:80 W0927 05:50:58.494] TIDE_PORT_80_TCP=tcp://10.0.180.53:80 W0927 05:50:58.494] TIDE_PORT_80_TCP_ADDR=10.0.180.53 W0927 05:50:58.494] TIDE_PORT_80_TCP_PORT=80 W0927 05:50:58.494] TIDE_PORT_80_TCP_PROTO=tcp W0927 05:50:58.494] TIDE_SERVICE_HOST=10.0.180.53 W0927 05:50:58.494] TIDE_SERVICE_PORT=80 W0927 05:50:58.495] WORKSPACE=/workspace W0927 05:50:58.495] _=./test-infra/jenkins/bootstrap.py W0927 05:50:58.495] 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=1', '--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-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', '--test-azure-file-csi-driver=True') W0927 05:50:58.501] 2019/09/27 05:50:58 azure.go:230: Reading credentials file /etc/azure-cred/credentials W0927 05:50:58.501] 2019/09/27 05:50:58 process.go:153: Running: make -C /go/src/k8s.io/kubernetes bazel-release W0927 05:50:58.553] Extracting Bazel installation... I0927 05:50:58.654] make: Entering directory '/go/src/k8s.io/kubernetes' W0927 05:51:07.652] Starting local Bazel server and connecting to it... W0927 05:51:09.372] Loading: W0927 05:51:09.375] Loading: 0 packages loaded W0927 05:51:10.377] Loading: 0 packages loaded W0927 05:51:11.957] Loading: 0 packages loaded W0927 05:51:13.379] Loading: 0 packages loaded W0927 05:51:15.228] Loading: 0 packages loaded W0927 05:51:16.379] Loading: 0 packages loaded W0927 05:51:16.379] currently loading: build/release-tars W0927 05:51:18.481] Loading: 0 packages loaded W0927 05:51:18.481] currently loading: build/release-tars W0927 05:51:18.854] Analyzing: target //build/release-tars:release-tars (1 packages loaded, 0 targets configured) W0927 05:51:20.296] Analyzing: target //build/release-tars:release-tars (243 packages loaded, 1098 targets configured) W0927 05:51:21.957] Analyzing: target //build/release-tars:release-tars (1010 packages loaded, 4963 targets configured) W0927 05:51:23.865] Analyzing: target //build/release-tars:release-tars (1988 packages loaded, 12589 targets configured) W0927 05:51:26.062] Analyzing: target //build/release-tars:release-tars (2695 packages loaded, 21679 targets configured) W0927 05:51:28.959] Analyzing: target //build/release-tars:release-tars (3027 packages loaded, 27097 targets configured) W0927 05:51:32.487] Analyzing: target //build/release-tars:release-tars (3066 packages loaded, 30035 targets configured) W0927 05:51:36.070] Analyzing: target //build/release-tars:release-tars (3072 packages loaded, 34046 targets configured) W0927 05:51:53.894] INFO: Analysed target //build/release-tars:release-tars (3072 packages loaded, 42238 targets configured). W0927 05:51:53.897] Building: checking cached actions W0927 05:51:53.898] INFO: Found 1 target... W0927 05:51:54.070] [0 / 14] [-----] BazelWorkspaceStatusAction stable-status.txt W0927 05:52:02.918] [119 / 5,296] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 4s linux-sandbox ... (8 actions running) W0927 05:52:11.413] [160 / 5,296] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 13s linux-sandbox ... (8 actions running) W0927 05:52:20.744] [295 / 5,296] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 22s linux-sandbox ... (8 actions running) W0927 05:52:31.472] [362 / 5,296] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 33s linux-sandbox ... (8 actions running) W0927 05:52:43.806] [595 / 5,296] GoCompile vendor/gonum.org/v1/gonum/graph/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/gonum.org/v1/gonum/graph.a; 1s linux-sandbox ... (8 actions running) W0927 05:52:59.625] [696 / 5,296] GoCompile vendor/github.com/aws/aws-sdk-go/aws/endpoints/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/aws/aws-sdk-go/aws/endpoints.a; 2s linux-sandbox ... (8 actions running) W0927 05:53:16.182] [777 / 5,296] GoCompile vendor/github.com/vmware/govmomi/vim25/types/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/types.a; 6s linux-sandbox ... (8 actions running) W0927 05:53:35.346] [932 / 5,296] GoCompile vendor/github.com/vmware/govmomi/object/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/object.a; 3s linux-sandbox ... (8 actions, 7 running) W0927 05:53:57.915] [1,062 / 5,296] GoCompile staging/src/k8s.io/apimachinery/third_party/forked/golang/json/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/apimachinery/third_party/forked/golang/json.a; 1s linux-sandbox ... (8 actions running) W0927 05:54:23.301] [1,198 / 5,296] GoCompile vendor/github.com/coreos/etcd/etcdserver/etcdserverpb/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/coreos/etcd/etcdserver/etcdserverpb.a; 2s linux-sandbox ... (8 actions, 7 running) W0927 05:54:52.417] [1,695 / 5,296] Compiling vendor/golang.org/x/sys/unix/linux_amd64_stripped/go_default_library%linux_amd64%cgo_codegen%/fcntl.cgo2.c; 0s linux-sandbox ... (7 actions running) W0927 05:55:25.919] [2,058 / 5,296] GoCompile vendor/github.com/prometheus/procfs/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/prometheus/procfs.a; 0s linux-sandbox ... (8 actions, 7 running) W0927 05:56:04.495] [2,478 / 5,296] GoCompile vendor/github.com/Azure/azure-sdk-for-go/services/network/mgmt/2019-06-01/network/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/Azure/azure-sdk-for-go/services/network/mgmt/2019-06-01/network.a; 15s linux-sandbox ... (8 actions, 7 running) W0927 05:56:49.751] [2,704 / 5,296] GoPath pkg/generated/openapi/zz_generated.openapi~gopath/src/k8s.io/kubernetes/vendor/github.com/go-openapi/spec/bindata.go; 2s linux-sandbox ... (8 actions, 7 running) W0927 05:57:49.454] [2,820 / 5,296] ; 53s linux-sandbox ... (8 actions running) W0927 05:58:51.979] [2,920 / 5,296] PackageTar build/release-tars/kubernetes-src.tar.gz; 52s linux-sandbox ... (8 actions, 7 running) W0927 06:00:01.523] [3,233 / 5,296] GoCompile staging/src/k8s.io/client-go/kubernetes/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes.a; 1s linux-sandbox ... (8 actions, 7 running) W0927 06:01:22.905] [3,756 / 5,296] GoCompile staging/src/k8s.io/apiextensions-apiserver/test/integration/fixtures/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/apiextensions-apiserver/test/integration/fixtures.a; 2s linux-sandbox ... (8 actions, 7 running) W0927 06:02:55.765] [4,371 / 5,296] GoCompile staging/src/k8s.io/client-go/kubernetes/typed/policy/v1beta1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/policy/v1beta1.a; 1s linux-sandbox ... (8 actions, 7 running) W0927 06:04:41.912] [4,806 / 5,296] GoCompile staging/src/k8s.io/client-go/kubernetes/fake/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/fake.a; 0s linux-sandbox ... (8 actions, 7 running) W0927 06:06:44.693] [5,177 / 5,296] GoLink cmd/kube-scheduler/linux_amd64_pure_stripped/kube-scheduler; 28s linux-sandbox ... (8 actions, 7 running) W0927 06:09:09.413] [5,232 / 5,296] GoLink cmd/hyperkube/hyperkube; 140s linux-sandbox ... (8 actions running) W0927 06:11:45.351] Target //build/release-tars:release-tars up-to-date: W0927 06:11:45.351] bazel-bin/build/release-tars/kubernetes-client-linux-amd64.tar.gz W0927 06:11:45.351] bazel-bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz W0927 06:11:45.352] bazel-bin/build/release-tars/kubernetes-server-linux-amd64.tar.gz W0927 06:11:45.352] bazel-bin/build/release-tars/kubernetes-manifests.tar.gz W0927 06:11:45.352] bazel-bin/build/release-tars/kubernetes-test-portable.tar.gz W0927 06:11:45.352] bazel-bin/build/release-tars/kubernetes-test-linux-amd64.tar.gz W0927 06:11:45.352] bazel-bin/build/release-tars/kubernetes.tar.gz W0927 06:11:45.352] bazel-bin/build/release-tars/kubernetes-src.tar.gz W0927 06:11:45.368] INFO: Elapsed time: 1246.780s, Critical Path: 383.70s W0927 06:11:45.369] INFO: 5205 processes: 5205 linux-sandbox. W0927 06:11:45.373] INFO: Build completed successfully, 5296 total actions W0927 06:11:45.375] INFO: Build completed successfully, 5296 total actions W0927 06:11:45.389] 2019/09/27 06:11:45 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes bazel-release' finished in 20m46.887750594s W0927 06:11:45.390] 2019/09/27 06:11:45 util.go:277: Flushing memory. I0927 06:11:45.490] make: Leaving directory '/go/src/k8s.io/kubernetes' W0927 06:12:18.854] 2019/09/27 06:12:18 azure.go:899: Deleting resource group: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d. W0927 06:12:19.316] 2019/09/27 06:12:19 azure.go:780: downloading /workspace/aks455019149/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json. W0927 06:12:19.316] 2019/09/27 06:12:19 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json W0927 06:12:19.512] 2019/09/27 06:12:19 azure.go:527: 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. W0927 06:12:19.513] 2019/09/27 06:12:19 util.go:42: curl https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz W0927 06:12:20.755] 2019/09/27 06:12:20 azure.go:554: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes . W0927 06:12:20.755] 2019/09/27 06:12:20 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1 W0927 06:12:20.920] 2019/09/27 06:12:20 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 165.329175ms W0927 06:12:20.921] 2019/09/27 06:12:20 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks455019149/kubernetes.json --output-directory /workspace/aks455019149 I0927 06:12:21.124] INFO[0000] Generating assets into /workspace/aks455019149... W0927 06:12:37.612] 2019/09/27 06:12:37 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks455019149/kubernetes.json --output-directory /workspace/aks455019149' finished in 16.691520448s W0927 06:12:37.615] 2019/09/27 06:12:37 azure.go:625: Setting kubeconfig env variable: kubeconfig path: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json. W0927 06:12:37.615] 2019/09/27 06:12:37 azure.go:627: Creating resource group: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d. W0927 06:12:37.615] 2019/09/27 06:12:37 azure.go:629: Creating Azure resource group: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d for cluster deployment. W0927 06:12:39.196] 2019/09/27 06:12:39 azure.go:634: Validating deployment ARM templates. W0927 06:12:40.993] 2019/09/27 06:12:40 azure.go:640: Deploying cluster kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d in resource group kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d. W0927 06:21:47.052] 2019/09/27 06:21:47 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version W0927 06:21:47.693] 2019/09/27 06:21:47 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 641.225747ms W0927 06:21:47.694] 2019/09/27 06:21:47 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false get nodes -oyaml W0927 06:21:48.973] 2019/09/27 06:21:48 process.go:155: Step './cluster/kubectl.sh --match-server-version=false get nodes -oyaml' finished in 1.27945877s W0927 06:21:48.973] 2019/09/27 06:21:48 azure.go:944: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos. W0927 06:21:48.974] 2019/09/27 06:21:48 azure.go:944: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos. W0927 06:21:48.974] 2019/09/27 06:21:48 process.go:153: Running: kubectl get nodes --no-headers W0927 06:21:49.531] 2019/09/27 06:21:49 process.go:155: Step 'kubectl get nodes --no-headers' finished in 556.672294ms W0927 06:21:49.531] 2019/09/27 06:21:49 e2e.go:462: Cluster nodes: W0927 06:21:49.532] k8s-agentpool1-10768025-0 NotReady 15s v1.15.0 W0927 06:21:49.532] k8s-agentpool1-10768025-1 NotReady 15s v1.15.0 W0927 06:21:49.532] k8s-master-10768025-0 NotReady 15s v1.15.0 W0927 06:21:49.532] 2019/09/27 06:21:49 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version W0927 06:21:49.934] 2019/09/27 06:21:49 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 402.956708ms W0927 06:21:49.934] 2019/09/27 06:21:49 process.go:153: Running: make e2e-test I0927 06:21:50.035] go test -v -timeout=30m ./test/e2e "-ginkgo.noColor" W0927 06:21:50.135] go: finding github.com/Azure/go-autorest v11.5.1+incompatible W0927 06:21:50.136] go: finding github.com/PuerkitoBio/purell v1.1.1 W0927 06:21:50.136] go: finding github.com/googleapis/gnostic v0.2.0 W0927 06:21:50.136] go: finding github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e W0927 06:21:50.136] go: finding github.com/jonboulle/clockwork v0.1.0 W0927 06:21:50.136] go: finding github.com/golang/protobuf v1.3.0 W0927 06:21:50.136] go: finding github.com/docker/distribution v0.0.0-20170905204447-5db89f0ca686 W0927 06:21:50.319] go: finding golang.org/x/net v0.0.0-20190301231341-16b79f2e4e95 W0927 06:21:50.323] go: finding k8s.io/cluster-bootstrap v0.0.0-20190313124217-0fa624df11e9 W0927 06:21:50.325] go: finding k8s.io/legacy-cloud-providers v0.0.0-20190624091455-d8621ceb9c64 W0927 06:21:50.722] go: finding github.com/coreos/etcd v3.3.12+incompatible W0927 06:21:50.731] go: finding github.com/mailru/easyjson v0.0.0-20190312143242-1de009706dbe W0927 06:21:50.789] go: finding k8s.io/apimachinery v0.0.0-20190313205120-d7deff9243b1 W0927 06:21:50.802] go: finding github.com/prometheus/client_golang v0.9.2 W0927 06:21:50.938] go: finding github.com/imdario/mergo v0.3.7 W0927 06:21:50.950] go: finding github.com/coreos/go-semver v0.3.0 W0927 06:21:51.070] go: finding github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf W0927 06:21:51.441] go: finding k8s.io/klog v0.2.0 W0927 06:21:51.496] go: finding github.com/elazarl/goproxy/ext v0.0.0-20190410145444-c548f45dcf1d W0927 06:21:51.549] go: finding github.com/xiang90/probing v0.0.0-20190116061207-43a291ad63a2 W0927 06:21:51.855] go: finding github.com/coreos/bbolt v1.3.2 W0927 06:21:51.964] go: finding gopkg.in/warnings.v0 v0.1.1 W0927 06:21:52.022] go: finding github.com/pelletier/go-toml v1.4.0 W0927 06:21:52.055] go: finding github.com/pborman/uuid v0.0.0-20180906182336-adf5a7427709 W0927 06:21:52.080] go: finding github.com/go-openapi/swag v0.19.0 W0927 06:21:52.387] go: finding github.com/Azure/azure-storage-file-go v0.5.0 W0927 06:21:52.394] go: finding sigs.k8s.io/yaml v1.1.0 W0927 06:21:52.503] go: finding github.com/prometheus/common v0.2.0 W0927 06:21:52.603] go: finding k8s.io/api v0.0.0-20190313235455-40a48860b5ab W0927 06:21:52.627] go: finding k8s.io/cli-runtime v0.0.0-20190314001948-2899ed30580f W0927 06:21:52.693] go: finding golang.org/x/crypto v0.0.0-20190228161510-8dd112bcdc25 W0927 06:21:52.942] go: finding github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 W0927 06:21:53.038] go: finding github.com/satori/go.uuid v1.2.0 W0927 06:21:53.088] go: finding contrib.go.opencensus.io/exporter/ocagent v0.2.0 W0927 06:21:53.231] go: finding github.com/tmc/grpc-websocket-proxy v0.0.0-20190109142713-0ad062ec5ee5 W0927 06:21:53.358] go: finding github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf W0927 06:21:53.489] go: finding github.com/spf13/cobra v0.0.3 W0927 06:21:53.532] go: finding k8s.io/kubernetes v1.14.0 W0927 06:21:53.587] go: finding github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0 W0927 06:21:53.627] go: finding golang.org/x/sys v0.0.0-20190308023053-584f3b12f43e W0927 06:21:53.792] go: finding github.com/go-kit/kit v0.8.0 W0927 06:21:53.860] go: finding github.com/dnaeon/go-vcr v1.0.1 W0927 06:21:54.089] go: finding github.com/google/btree v1.0.0 W0927 06:21:54.123] go: finding github.com/stretchr/objx v0.1.1 W0927 06:21:54.371] go: finding github.com/rubiojr/go-vhd v0.0.0-20160810183302-0bfd3b39853c W0927 06:21:54.455] go: finding github.com/coreos/pkg v0.0.0-20180928190104-399ea9e2e55f W0927 06:21:54.631] go: finding github.com/rogpeppe/go-charset v0.0.0-20180617210344-2471d30d28b4 W0927 06:21:54.679] go: finding github.com/Azure/azure-sdk-for-go v21.4.0+incompatible W0927 06:21:55.123] go: finding github.com/gogo/protobuf v1.2.1 W0927 06:21:55.158] go: finding k8s.io/client-go v11.0.0+incompatible W0927 06:21:55.315] go: finding github.com/pkg/errors v0.8.1 W0927 06:21:55.316] go: finding github.com/go-stack/stack v1.8.0 W0927 06:21:55.318] go: finding github.com/prometheus/procfs v0.0.0-20190306233201-d0f344d83b0c W0927 06:21:55.368] go: finding go.uber.org/zap v1.9.1 W0927 06:21:55.906] go: finding k8s.io/cloud-provider v0.0.0-20190308083404-05ccf96446f8 W0927 06:21:55.919] go: finding github.com/BurntSushi/toml v0.3.1 W0927 06:21:55.934] go: finding golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421 W0927 06:21:56.103] go: finding k8s.io/apiextensions-apiserver v0.0.0-20190315093550-53c4693659ed W0927 06:21:56.212] go: finding github.com/json-iterator/go v1.1.5 W0927 06:21:56.467] go: finding github.com/stretchr/testify v1.3.0 W0927 06:21:56.515] go: finding github.com/ugorji/go v1.1.4 W0927 06:21:56.610] go: finding github.com/julienschmidt/httprouter v1.2.0 W0927 06:21:56.896] go: finding github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc W0927 06:21:57.112] go: finding github.com/dgrijalva/jwt-go v3.2.0+incompatible W0927 06:21:57.125] go: finding github.com/hashicorp/golang-lru v0.5.1 W0927 06:21:57.163] go: finding github.com/onsi/ginkgo v1.7.0 W0927 06:21:57.351] go: finding k8s.io/utils v0.0.0-20190221042446-c2654d5206da W0927 06:21:57.610] go: finding github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 W0927 06:21:57.707] go: finding google.golang.org/grpc v1.19.0 W0927 06:21:57.723] go: finding github.com/google/uuid v1.1.1 W0927 06:21:57.859] go: finding github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515 W0927 06:21:58.112] go: finding github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef W0927 06:21:58.327] go: finding github.com/sirupsen/logrus v1.2.0 W0927 06:21:58.449] go: finding github.com/go-openapi/jsonpointer v0.19.0 W0927 06:21:58.475] go: finding sigs.k8s.io/kustomize v2.0.3+incompatible W0927 06:21:58.589] go: finding github.com/census-instrumentation/opencensus-proto v0.1.0 W0927 06:21:58.677] go: finding golang.org/x/sync v0.0.0-20190227155943-e225da77a7e6 W0927 06:21:58.978] go: finding github.com/elazarl/goproxy v0.0.0-20190410145444-c548f45dcf1d W0927 06:21:59.024] go: finding github.com/evanphx/json-patch v3.0.0+incompatible W0927 06:21:59.141] go: finding github.com/mwitkow/go-conntrack v0.0.0-20161129095857-cc309e4a2223 W0927 06:21:59.170] go: finding gopkg.in/square/go-jose.v2 v2.3.0 W0927 06:21:59.187] go: finding github.com/GoogleCloudPlatform/k8s-cloud-provider v0.0.0-20181220005116-f8e995905100 W0927 06:21:59.451] go: finding google.golang.org/api v0.1.0 W0927 06:21:59.531] go: finding github.com/go-openapi/spec v0.19.0 W0927 06:21:59.820] go: finding google.golang.org/genproto v0.0.0-20190307195333-5fe7a883aa19 W0927 06:21:59.897] go: finding golang.org/x/text v0.3.0 W0927 06:22:00.217] go: finding go.uber.org/multierr v1.1.0 W0927 06:22:00.289] go: finding gopkg.in/yaml.v2 v2.2.2 W0927 06:22:00.394] go: finding github.com/docker/spdystream v0.0.0-20181023171402-6480d4af844c W0927 06:22:00.665] go: finding github.com/vmware/govmomi v0.20.1 W0927 06:22:01.000] go: finding github.com/kubernetes-csi/external-snapshotter v1.0.1 W0927 06:22:01.112] go: finding github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 W0927 06:22:01.645] go: finding github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd W0927 06:22:01.943] go: finding github.com/go-openapi/jsonreference v0.19.0 W0927 06:22:01.947] go: finding github.com/fatih/camelcase v1.0.0 W0927 06:22:01.967] go: finding github.com/pmezard/go-difflib v1.0.0 W0927 06:22:02.496] go: finding github.com/kisielk/errcheck v1.1.0 W0927 06:22:02.503] go: finding github.com/marstr/guid v1.1.0 W0927 06:22:02.563] go: finding google.golang.org/appengine v1.4.0 W0927 06:22:02.632] go: finding gopkg.in/inf.v0 v0.9.1 W0927 06:22:02.664] go: finding gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 W0927 06:22:02.933] go: finding cloud.google.com/go v0.34.0 W0927 06:22:02.943] go: finding github.com/matttproud/golang_protobuf_extensions v1.0.1 W0927 06:22:03.127] go: finding k8s.io/apiserver v0.0.0-20190313205120-8b27c41bdbb1 W0927 06:22:03.407] go: finding github.com/emicklei/go-restful v2.9.3+incompatible W0927 06:22:03.562] go: finding golang.org/x/lint v0.0.0-20190227174305-5b3e6a55c961 W0927 06:22:03.893] go: finding github.com/grpc-ecosystem/go-grpc-middleware v1.0.0 W0927 06:22:04.110] go: finding github.com/onsi/gomega v1.4.3 W0927 06:22:04.317] go: finding gopkg.in/gcfg.v1 v1.2.0 W0927 06:22:04.384] go: finding github.com/kr/pretty v0.1.0 W0927 06:22:04.440] go: finding go.uber.org/atomic v1.3.2 W0927 06:22:04.566] go: finding github.com/inconshreveable/mousetrap v1.0.0 W0927 06:22:04.652] go: finding k8s.io/component-base v0.0.0-20190313120452-4727f38490bc W0927 06:22:04.793] go: finding k8s.io/csi-translation-lib v0.0.0-20190313124639-7f5cabc6aac8 W0927 06:22:04.915] go: finding k8s.io/kube-aggregator v0.0.0-20190401185513-77f9841f26eb W0927 06:22:05.118] go: finding github.com/Azure/azure-pipeline-go v0.2.1 W0927 06:22:05.120] go: finding github.com/gregjones/httpcache v0.0.0-20190212212710-3befbb6ad0cc W0927 06:22:05.210] go: finding github.com/hpcloud/tail v1.0.0 W0927 06:22:05.634] go: finding github.com/soheilhy/cmux v0.1.4 W0927 06:22:05.807] go: finding golang.org/x/tools v0.0.0-20190226205152-f727befe758c W0927 06:22:05.860] go: finding github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 W0927 06:22:06.023] go: finding honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099 W0927 06:22:06.146] go: finding go.opencensus.io v0.18.0 W0927 06:22:06.213] go: finding github.com/opencontainers/go-digest v1.0.0-rc1 W0927 06:22:07.031] go: finding github.com/konsorten/go-windows-terminal-sequences v1.0.1 W0927 06:22:07.057] go: finding github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 W0927 06:22:07.090] go: finding github.com/aws/aws-sdk-go v1.16.26 W0927 06:22:07.106] go: finding github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b W0927 06:22:07.140] go: finding github.com/golang/mock v1.1.1 W0927 06:22:07.188] go: finding golang.org/x/time v0.0.0-20181108054448-85acf8d2951c W0927 06:22:07.200] go: finding k8s.io/kube-openapi v0.0.0-20190306001800-15615b16d372 W0927 06:22:07.677] go: finding github.com/gorilla/websocket v1.4.0 W0927 06:22:07.760] go: finding github.com/apache/thrift v0.0.0-20180902110319-2566ecd5d999 W0927 06:22:07.874] go: finding gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 W0927 06:22:07.896] go: finding github.com/kisielk/gotool v1.0.0 W0927 06:22:07.920] go: finding github.com/container-storage-interface/spec v1.1.0 W0927 06:22:07.960] go: finding github.com/spf13/pflag v1.0.3 W0927 06:22:08.203] go: finding github.com/ghodss/yaml v1.0.0 W0927 06:22:08.352] go: finding github.com/go-logfmt/logfmt v0.3.0 W0927 06:22:08.366] go: finding github.com/openzipkin/zipkin-go v0.1.1 W0927 06:22:08.608] go: finding go.etcd.io/bbolt v1.3.2 W0927 06:22:08.715] go: finding github.com/davecgh/go-spew v1.1.1 W0927 06:22:08.730] go: finding gopkg.in/fsnotify.v1 v1.4.7 W0927 06:22:08.919] go: finding github.com/kr/pty v1.1.5 W0927 06:22:09.139] go: finding gopkg.in/alecthomas/kingpin.v2 v2.2.6 W0927 06:22:09.279] go: finding github.com/spf13/afero v1.2.2 W0927 06:22:09.287] go: finding github.com/peterbourgon/diskv v2.0.1+incompatible W0927 06:22:09.772] go: finding github.com/google/go-cmp v0.2.0 W0927 06:22:09.840] go: finding github.com/grpc-ecosystem/grpc-gateway v1.5.0 W0927 06:22:09.883] go: finding github.com/fsnotify/fsnotify v1.4.7 W0927 06:22:09.885] go: finding github.com/kr/text v0.1.0 W0927 06:22:10.879] go: finding github.com/client9/misspell v0.3.4 W0927 06:22:10.935] go: finding golang.org/x/exp v0.0.0-20190121172915-509febef88a4 W0927 06:22:16.427] go: finding github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af W0927 06:22:16.955] go: downloading k8s.io/api v0.0.0-20190313235455-40a48860b5ab W0927 06:22:16.956] go: downloading k8s.io/kubernetes v1.14.0 W0927 06:22:16.956] go: downloading k8s.io/client-go v11.0.0+incompatible W0927 06:22:16.957] go: downloading github.com/onsi/gomega v1.4.3 W0927 06:22:16.958] go: downloading github.com/onsi/ginkgo v1.7.0 W0927 06:22:16.960] go: downloading github.com/pelletier/go-toml v1.4.0 W0927 06:22:16.961] go: downloading google.golang.org/grpc v1.19.0 W0927 06:22:16.962] go: downloading k8s.io/legacy-cloud-providers v0.0.0-20190624091455-d8621ceb9c64 W0927 06:22:17.114] go: extracting github.com/pelletier/go-toml v1.4.0 W0927 06:22:17.115] go: extracting github.com/onsi/gomega v1.4.3 W0927 06:22:17.146] go: extracting github.com/onsi/ginkgo v1.7.0 W0927 06:22:17.159] go: downloading k8s.io/apimachinery v0.0.0-20190313205120-d7deff9243b1 W0927 06:22:17.159] go: downloading github.com/golang/protobuf v1.3.0 W0927 06:22:17.190] go: downloading github.com/kubernetes-csi/external-snapshotter v1.0.1 W0927 06:22:17.304] go: extracting k8s.io/legacy-cloud-providers v0.0.0-20190624091455-d8621ceb9c64 W0927 06:22:17.535] go: extracting google.golang.org/grpc v1.19.0 W0927 06:22:17.646] go: extracting github.com/golang/protobuf v1.3.0 W0927 06:22:17.668] go: extracting k8s.io/apimachinery v0.0.0-20190313205120-d7deff9243b1 W0927 06:22:17.677] go: extracting k8s.io/api v0.0.0-20190313235455-40a48860b5ab W0927 06:22:17.743] go: downloading github.com/Azure/azure-sdk-for-go v21.4.0+incompatible W0927 06:22:17.746] go: extracting k8s.io/client-go v11.0.0+incompatible W0927 06:22:17.758] go: downloading k8s.io/cloud-provider v0.0.0-20190308083404-05ccf96446f8 W0927 06:22:17.763] go: downloading github.com/Azure/go-autorest v11.5.1+incompatible W0927 06:22:17.885] go: downloading github.com/Azure/azure-storage-file-go v0.5.0 W0927 06:22:17.886] go: downloading github.com/rubiojr/go-vhd v0.0.0-20160810183302-0bfd3b39853c W0927 06:22:17.888] go: downloading github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf W0927 06:22:17.955] go: extracting github.com/Azure/go-autorest v11.5.1+incompatible W0927 06:22:17.962] go: extracting github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf W0927 06:22:18.076] go: extracting github.com/Azure/azure-storage-file-go v0.5.0 W0927 06:22:18.091] go: downloading github.com/pborman/uuid v0.0.0-20180906182336-adf5a7427709 W0927 06:22:18.138] go: extracting github.com/pborman/uuid v0.0.0-20180906182336-adf5a7427709 W0927 06:22:18.147] go: downloading golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421 W0927 06:22:18.231] go: extracting golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421 W0927 06:22:18.244] go: downloading github.com/Azure/azure-pipeline-go v0.2.1 W0927 06:22:18.286] go: extracting github.com/Azure/azure-pipeline-go v0.2.1 W0927 06:22:18.293] go: downloading golang.org/x/net v0.0.0-20190301231341-16b79f2e4e95 W0927 06:22:18.312] go: extracting github.com/rubiojr/go-vhd v0.0.0-20160810183302-0bfd3b39853c W0927 06:22:18.319] go: extracting k8s.io/cloud-provider v0.0.0-20190308083404-05ccf96446f8 W0927 06:22:18.325] go: downloading github.com/dgrijalva/jwt-go v3.2.0+incompatible W0927 06:22:18.371] go: downloading github.com/googleapis/gnostic v0.2.0 W0927 06:22:18.398] go: extracting github.com/dgrijalva/jwt-go v3.2.0+incompatible W0927 06:22:18.408] go: downloading contrib.go.opencensus.io/exporter/ocagent v0.2.0 W0927 06:22:18.453] go: extracting contrib.go.opencensus.io/exporter/ocagent v0.2.0 W0927 06:22:18.870] go: extracting github.com/googleapis/gnostic v0.2.0 W0927 06:22:19.081] go: extracting golang.org/x/net v0.0.0-20190301231341-16b79f2e4e95 W0927 06:22:19.165] go: downloading k8s.io/utils v0.0.0-20190221042446-c2654d5206da W0927 06:22:19.181] go: downloading github.com/gogo/protobuf v1.2.1 W0927 06:22:19.254] go: extracting k8s.io/utils v0.0.0-20190221042446-c2654d5206da W0927 06:22:19.264] go: downloading go.opencensus.io v0.18.0 W0927 06:22:19.441] go: extracting go.opencensus.io v0.18.0 W0927 06:22:19.463] go: downloading sigs.k8s.io/yaml v1.1.0 W0927 06:22:19.511] go: extracting sigs.k8s.io/yaml v1.1.0 W0927 06:22:19.512] go: downloading google.golang.org/api v0.1.0 W0927 06:22:20.688] go: extracting github.com/gogo/protobuf v1.2.1 W0927 06:22:20.862] go: downloading github.com/census-instrumentation/opencensus-proto v0.1.0 W0927 06:22:21.003] go: extracting github.com/census-instrumentation/opencensus-proto v0.1.0 W0927 06:22:21.028] go: downloading golang.org/x/time v0.0.0-20181108054448-85acf8d2951c W0927 06:22:21.068] go: extracting golang.org/x/time v0.0.0-20181108054448-85acf8d2951c W0927 06:22:21.071] go: downloading github.com/google/uuid v1.1.1 W0927 06:22:21.113] go: extracting github.com/google/uuid v1.1.1 W0927 06:22:21.121] go: downloading gopkg.in/inf.v0 v0.9.1 W0927 06:22:21.176] go: extracting gopkg.in/inf.v0 v0.9.1 W0927 06:22:21.179] go: downloading google.golang.org/genproto v0.0.0-20190307195333-5fe7a883aa19 W0927 06:22:24.611] go: extracting google.golang.org/genproto v0.0.0-20190307195333-5fe7a883aa19 W0927 06:22:25.066] go: downloading github.com/hashicorp/golang-lru v0.5.1 W0927 06:22:25.138] go: extracting github.com/hashicorp/golang-lru v0.5.1 W0927 06:22:25.141] go: downloading github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 W0927 06:22:25.172] go: extracting github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 W0927 06:22:25.256] go: downloading golang.org/x/crypto v0.0.0-20190228161510-8dd112bcdc25 W0927 06:22:25.836] go: extracting golang.org/x/crypto v0.0.0-20190228161510-8dd112bcdc25 W0927 06:22:25.905] go: downloading github.com/davecgh/go-spew v1.1.1 W0927 06:22:25.993] go: extracting google.golang.org/api v0.1.0 W0927 06:22:26.000] go: extracting github.com/davecgh/go-spew v1.1.1 W0927 06:22:26.545] go: downloading golang.org/x/text v0.3.0 W0927 06:22:27.405] go: extracting github.com/kubernetes-csi/external-snapshotter v1.0.1 W0927 06:22:27.416] go: downloading github.com/json-iterator/go v1.1.5 W0927 06:22:27.430] go: downloading k8s.io/klog v0.2.0 W0927 06:22:27.487] go: extracting k8s.io/klog v0.2.0 W0927 06:22:27.495] go: downloading golang.org/x/sync v0.0.0-20190227155943-e225da77a7e6 W0927 06:22:27.535] go: extracting github.com/json-iterator/go v1.1.5 W0927 06:22:27.542] go: extracting golang.org/x/sync v0.0.0-20190227155943-e225da77a7e6 W0927 06:22:27.554] go: downloading github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 W0927 06:22:27.602] go: extracting github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 W0927 06:22:27.618] go: downloading github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef W0927 06:22:27.660] go: extracting github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef W0927 06:22:27.665] go: downloading gopkg.in/yaml.v2 v2.2.2 W0927 06:22:27.732] go: extracting gopkg.in/yaml.v2 v2.2.2 W0927 06:22:27.743] go: downloading github.com/prometheus/client_golang v0.9.2 W0927 06:22:27.884] go: extracting github.com/prometheus/client_golang v0.9.2 W0927 06:22:27.908] go: downloading k8s.io/kube-openapi v0.0.0-20190306001800-15615b16d372 W0927 06:22:28.849] go: extracting github.com/Azure/azure-sdk-for-go v21.4.0+incompatible W0927 06:22:28.946] go: extracting k8s.io/kube-openapi v0.0.0-20190306001800-15615b16d372 W0927 06:22:30.215] go: extracting k8s.io/kubernetes v1.14.0 W0927 06:22:30.520] go: extracting golang.org/x/text v0.3.0 W0927 06:22:30.590] go: downloading github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 W0927 06:22:30.594] go: downloading github.com/satori/go.uuid v1.2.0 W0927 06:22:30.731] go: extracting github.com/satori/go.uuid v1.2.0 W0927 06:22:30.734] go: downloading github.com/prometheus/common v0.2.0 W0927 06:22:30.773] go: extracting github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 W0927 06:22:30.809] go: downloading github.com/prometheus/procfs v0.0.0-20190306233201-d0f344d83b0c W0927 06:22:30.832] go: extracting github.com/prometheus/common v0.2.0 W0927 06:22:30.910] go: extracting github.com/prometheus/procfs v0.0.0-20190306233201-d0f344d83b0c W0927 06:22:31.008] go: downloading github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 W0927 06:22:31.008] go: downloading github.com/container-storage-interface/spec v1.1.0 W0927 06:22:31.008] go: downloading github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd W0927 06:22:31.009] go: downloading github.com/marstr/guid v1.1.0 W0927 06:22:31.009] go: downloading github.com/matttproud/golang_protobuf_extensions v1.0.1 W0927 06:22:31.012] go: downloading github.com/hpcloud/tail v1.0.0 W0927 06:22:31.022] go: downloading golang.org/x/sys v0.0.0-20190308023053-584f3b12f43e W0927 06:22:31.111] go: extracting github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 W0927 06:22:31.130] go: extracting github.com/marstr/guid v1.1.0 W0927 06:22:31.151] go: extracting github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd W0927 06:22:31.192] go: extracting github.com/hpcloud/tail v1.0.0 W0927 06:22:31.195] go: extracting github.com/matttproud/golang_protobuf_extensions v1.0.1 W0927 06:22:31.195] go: downloading gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 W0927 06:22:31.196] go: downloading gopkg.in/fsnotify.v1 v1.4.7 W0927 06:22:31.272] go: extracting github.com/container-storage-interface/spec v1.1.0 W0927 06:22:31.272] go: extracting gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 W0927 06:22:31.286] go: extracting gopkg.in/fsnotify.v1 v1.4.7 W0927 06:22:32.158] go: extracting golang.org/x/sys v0.0.0-20190308023053-584f3b12f43e W0927 06:22:32.867] go: downloading k8s.io/apiserver v0.0.0-20190313205120-8b27c41bdbb1 W0927 06:22:32.868] go: downloading k8s.io/apiextensions-apiserver v0.0.0-20190315093550-53c4693659ed W0927 06:22:32.870] go: downloading github.com/pkg/errors v0.8.1 W0927 06:22:32.871] go: downloading github.com/stretchr/testify v1.3.0 W0927 06:22:32.873] go: downloading github.com/imdario/mergo v0.3.7 W0927 06:22:32.873] go: downloading github.com/spf13/pflag v1.0.3 W0927 06:22:33.182] go: extracting github.com/pkg/errors v0.8.1 W0927 06:22:33.223] go: extracting github.com/imdario/mergo v0.3.7 W0927 06:22:33.225] go: downloading github.com/docker/distribution v0.0.0-20170905204447-5db89f0ca686 W0927 06:22:33.229] go: downloading k8s.io/component-base v0.0.0-20190313120452-4727f38490bc W0927 06:22:33.249] go: extracting github.com/spf13/pflag v1.0.3 W0927 06:22:33.298] go: extracting github.com/stretchr/testify v1.3.0 W0927 06:22:33.305] go: downloading k8s.io/kube-aggregator v0.0.0-20190401185513-77f9841f26eb W0927 06:22:33.418] go: extracting k8s.io/component-base v0.0.0-20190313120452-4727f38490bc W0927 06:22:33.423] go: downloading github.com/fatih/camelcase v1.0.0 W0927 06:22:33.464] go: extracting github.com/fatih/camelcase v1.0.0 W0927 06:22:33.465] go: downloading k8s.io/cli-runtime v0.0.0-20190314001948-2899ed30580f W0927 06:22:33.588] go: extracting k8s.io/apiserver v0.0.0-20190313205120-8b27c41bdbb1 W0927 06:22:33.595] go: extracting k8s.io/cli-runtime v0.0.0-20190314001948-2899ed30580f W0927 06:22:33.608] go: downloading k8s.io/cluster-bootstrap v0.0.0-20190313124217-0fa624df11e9 W0927 06:22:33.679] go: downloading gopkg.in/square/go-jose.v2 v2.3.0 W0927 06:22:33.681] go: downloading github.com/spf13/cobra v0.0.3 W0927 06:22:33.682] go: downloading github.com/pmezard/go-difflib v1.0.0 W0927 06:22:33.683] go: downloading github.com/evanphx/json-patch v3.0.0+incompatible W0927 06:22:33.684] go: downloading github.com/docker/spdystream v0.0.0-20181023171402-6480d4af844c W0927 06:22:33.793] go: extracting github.com/pmezard/go-difflib v1.0.0 W0927 06:22:33.796] go: downloading github.com/peterbourgon/diskv v2.0.1+incompatible W0927 06:22:33.814] go: extracting github.com/evanphx/json-patch v3.0.0+incompatible W0927 06:22:33.825] go: extracting k8s.io/cluster-bootstrap v0.0.0-20190313124217-0fa624df11e9 W0927 06:22:33.828] go: downloading github.com/gregjones/httpcache v0.0.0-20190212212710-3befbb6ad0cc W0927 06:22:33.831] go: downloading sigs.k8s.io/kustomize v2.0.3+incompatible W0927 06:22:33.872] go: extracting github.com/docker/spdystream v0.0.0-20181023171402-6480d4af844c W0927 06:22:33.893] go: downloading k8s.io/csi-translation-lib v0.0.0-20190313124639-7f5cabc6aac8 W0927 06:22:33.895] go: extracting github.com/spf13/cobra v0.0.3 W0927 06:22:33.912] go: extracting github.com/peterbourgon/diskv v2.0.1+incompatible W0927 06:22:33.926] go: extracting github.com/gregjones/httpcache v0.0.0-20190212212710-3befbb6ad0cc W0927 06:22:33.929] go: downloading github.com/google/btree v1.0.0 W0927 06:22:33.945] go: extracting gopkg.in/square/go-jose.v2 v2.3.0 W0927 06:22:34.000] go: extracting github.com/google/btree v1.0.0 W0927 06:22:34.018] go: extracting k8s.io/csi-translation-lib v0.0.0-20190313124639-7f5cabc6aac8 W0927 06:22:34.047] go: extracting github.com/docker/distribution v0.0.0-20170905204447-5db89f0ca686 W0927 06:22:34.700] go: extracting k8s.io/kube-aggregator v0.0.0-20190401185513-77f9841f26eb W0927 06:22:34.718] go: downloading github.com/opencontainers/go-digest v1.0.0-rc1 W0927 06:22:34.757] go: extracting github.com/opencontainers/go-digest v1.0.0-rc1 W0927 06:22:34.919] go: extracting sigs.k8s.io/kustomize v2.0.3+incompatible W0927 06:22:34.984] go: downloading github.com/ghodss/yaml v1.0.0 W0927 06:22:34.984] go: downloading github.com/go-openapi/spec v0.19.0 W0927 06:22:34.985] go: downloading github.com/emicklei/go-restful v2.9.3+incompatible W0927 06:22:35.039] go: extracting k8s.io/apiextensions-apiserver v0.0.0-20190315093550-53c4693659ed W0927 06:22:35.076] go: extracting github.com/ghodss/yaml v1.0.0 W0927 06:22:35.106] go: extracting github.com/emicklei/go-restful v2.9.3+incompatible W0927 06:22:35.179] go: extracting github.com/go-openapi/spec v0.19.0 W0927 06:22:35.198] go: downloading github.com/go-openapi/jsonreference v0.19.0 W0927 06:22:35.198] go: downloading github.com/go-openapi/swag v0.19.0 W0927 06:22:35.198] go: downloading github.com/go-openapi/jsonpointer v0.19.0 W0927 06:22:35.233] go: extracting github.com/go-openapi/jsonreference v0.19.0 W0927 06:22:35.234] go: downloading github.com/PuerkitoBio/purell v1.1.1 W0927 06:22:35.269] go: extracting github.com/go-openapi/jsonpointer v0.19.0 W0927 06:22:35.277] go: extracting github.com/go-openapi/swag v0.19.0 W0927 06:22:35.281] go: downloading github.com/mailru/easyjson v0.0.0-20190312143242-1de009706dbe W0927 06:22:35.297] go: extracting github.com/PuerkitoBio/purell v1.1.1 W0927 06:22:35.298] go: downloading github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 W0927 06:22:35.323] go: extracting github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 W0927 06:22:35.349] go: extracting github.com/mailru/easyjson v0.0.0-20190312143242-1de009706dbe I0927 06:23:26.292] Sep 27 06:23:26.292: INFO: The --provider flag is not set. Continuing as if --provider=skeleton had been used. I0927 06:23:26.292] === RUN TestE2E I0927 06:23:26.293] Running Suite: AzureFile CSI Driver End-to-End Tests I0927 06:23:26.293] ==================================================== I0927 06:23:26.293] Random Seed: 1569565406 - Will randomize all specs I0927 06:23:26.293] Will run 8 of 8 specs I0927 06:23:26.293] I0927 06:23:28.653] 2019/09/27 06:23:28 Attempting docker login with Azure service principal I0927 06:23:30.872] 2019/09/27 06:23:30 docker login is successful I0927 06:23:30.872] 2019/09/27 06:23:30 Installing Azure File CSI Driver... I0927 06:23:30.874] make[1]: Entering directory '/go/src/github.com/kubernetes-sigs/azurefile-csi-driver' I0927 06:23:30.874] # Use v2.11.0 helm to match tiller's version in clusters made by aks-engine I0927 06:23:30.875] curl https://raw.githubusercontent.com/helm/helm/master/scripts/get | DESIRED_VERSION=v2.11.0 bash I0927 06:23:30.900] % Total % Received % Xferd Average Speed Time Time Time Current I0927 06:23:30.900] Dload Upload Total Spent Left Speed I0927 06:23:30.991] 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 7034 100 7034 0 0 77469 0 --:--:-- --:--:-- --:--:-- 78155 I0927 06:23:31.007] Downloading https://get.helm.sh/helm-v2.11.0-linux-amd64.tar.gz I0927 06:23:32.251] Preparing to install helm and tiller into /usr/local/bin I0927 06:23:32.280] helm installed into /usr/local/bin/helm I0927 06:23:32.305] tiller installed into /usr/local/bin/tiller I0927 06:23:32.307] Run 'helm init' to configure helm. I0927 06:23:32.322] # Make sure tiller is ready I0927 06:23:32.323] kubectl wait pod -l name=tiller --namespace kube-system --for condition=ready I0927 06:23:32.839] pod/tiller-deploy-54c96cb5df-n8lhd condition met I0927 06:23:32.842] helm version I0927 06:23:32.894] Client: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I0927 06:23:33.812] Server: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I0927 06:23:33.817] # Use IMAGE_VERSION from env var if it is defined I0927 06:23:33.818] # Only build and push the image if it does not exist in the registry I0927 06:23:33.819] docker pull k8sprowinternal.azurecr.io/azurefile-csi:v0.4.0 || make azurefile-container push I0927 06:23:34.113] v0.4.0: Pulling from azurefile-csi I0927 06:23:34.114] 092586df9206: Pulling fs layer I0927 06:23:34.114] 1acecfad6be1: Pulling fs layer I0927 06:23:34.115] 4d6924702a2e: Pulling fs layer I0927 06:23:34.609] 4d6924702a2e: Verifying Checksum I0927 06:23:34.610] 4d6924702a2e: Download complete I0927 06:23:34.741] 092586df9206: Verifying Checksum I0927 06:23:34.741] 092586df9206: Download complete I0927 06:23:34.945] 1acecfad6be1: Verifying Checksum I0927 06:23:34.945] 1acecfad6be1: Download complete I0927 06:23:39.938] 092586df9206: Pull complete I0927 06:23:43.027] 1acecfad6be1: Pull complete I0927 06:23:43.826] 4d6924702a2e: Pull complete I0927 06:23:43.852] Digest: sha256:46835feeb296dfcb3aa18798c6c5646c0cd1e19ac4f595a2a84a17bcc405087d I0927 06:23:43.873] Status: Downloaded newer image for k8sprowinternal.azurecr.io/azurefile-csi:v0.4.0 I0927 06:23:43.876] make install-driver I0927 06:23:43.878] make[2]: Entering directory '/go/src/github.com/kubernetes-sigs/azurefile-csi-driver' I0927 06:23:43.878] helm install charts/latest/azurefile-csi-driver -n azurefile-csi-driver --namespace kube-system --wait \ I0927 06:23:43.878] --set image.pullPolicy=IfNotPresent \ I0927 06:23:43.878] --set image.repository=k8sprowinternal.azurecr.io/azurefile-csi \ I0927 06:23:43.879] --set image.tag=v0.4.0 I0927 06:24:42.681] NAME: azurefile-csi-driver I0927 06:24:44.013] LAST DEPLOYED: Fri Sep 27 06:23:44 2019 I0927 06:24:44.013] NAMESPACE: kube-system I0927 06:24:44.014] STATUS: DEPLOYED I0927 06:24:44.014] I0927 06:24:44.014] RESOURCES: I0927 06:24:44.014] ==> v1/Pod(related) I0927 06:24:44.014] NAME READY STATUS RESTARTS AGE I0927 06:24:44.014] csi-azurefile-node-7bvhj 3/3 Running 0 51s I0927 06:24:44.014] csi-azurefile-node-qkh7d 3/3 Running 0 51s I0927 06:24:44.014] csi-azurefile-controller-5f845667ff-696sd 6/6 Running 0 51s I0927 06:24:44.015] I0927 06:24:44.015] ==> v1/ServiceAccount I0927 06:24:44.015] I0927 06:24:44.015] NAME AGE I0927 06:24:44.015] csi-azurefile-controller-sa 52s I0927 06:24:44.015] I0927 06:24:44.015] ==> v1beta1/CustomResourceDefinition I0927 06:24:44.015] csidrivers.csi.storage.k8s.io 52s I0927 06:24:44.015] csinodeinfos.csi.storage.k8s.io 52s I0927 06:24:44.015] I0927 06:24:44.016] ==> v1/ClusterRole I0927 06:24:44.016] azurefile-external-provisioner-role 52s I0927 06:24:44.016] azurefile-external-attacher-role 52s I0927 06:24:44.016] azurefile-external-snapshotter-role 52s I0927 06:24:44.016] azurefile-cluster-driver-registrar-role 52s I0927 06:24:44.016] I0927 06:24:44.016] ==> v1/ClusterRoleBinding I0927 06:24:44.016] azurefile-csi-provisioner-binding 52s I0927 06:24:44.017] azurefile-csi-attacher-binding 52s I0927 06:24:44.017] azurefile-csi-snapshotter-binding 52s I0927 06:24:44.017] azurefile-csi-driver-registrar-binding 52s I0927 06:24:44.017] I0927 06:24:44.018] ==> v1/Service I0927 06:24:44.018] csi-azurefile-controller 52s I0927 06:24:44.018] I0927 06:24:44.019] ==> v1/DaemonSet I0927 06:24:44.019] csi-azurefile-node 51s I0927 06:24:44.019] I0927 06:24:44.019] ==> v1/Deployment I0927 06:24:44.020] csi-azurefile-controller 51s I0927 06:24:44.020] I0927 06:24:44.020] I0927 06:24:44.020] NOTES: I0927 06:24:44.021] The Azure File CSI Driver is getting deployed to your cluster. I0927 06:24:44.021] I0927 06:24:44.021] To check Azure File CSI Driver pods status, please run: I0927 06:24:44.021] I0927 06:24:44.022] kubectl --namespace=kube-system get pods --selector="release=azurefile-csi-driver" --watch I0927 06:24:44.022] I0927 06:24:44.022] make[2]: Leaving directory '/go/src/github.com/kubernetes-sigs/azurefile-csi-driver' I0927 06:24:44.023] make[1]: Leaving directory '/go/src/github.com/kubernetes-sigs/azurefile-csi-driver' I0927 06:24:44.023] 2019/09/27 06:24:44 Azure File CSI Driver installed I0927 06:24:44.023] Dynamic Provisioning I0927 06:24:44.023] should create a deployment object, write and read to it, delete the pod and write and read to it again I0927 06:24:44.024] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:129 I0927 06:24:44.024] [BeforeEach] Dynamic Provisioning I0927 06:24:44.024] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:24:44.024] STEP: Creating a kubernetes client I0927 06:24:44.025] Sep 27 06:24:44.017: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:24:44.025] I0927 06:24:44.017791 23192 azurefile.go:84] I0927 06:24:44.025] DRIVER INFORMATION: I0927 06:24:44.025] ------------------- I0927 06:24:44.025] Build Date: N/A I0927 06:24:44.025] Compiler: gc I0927 06:24:44.026] Driver Name: file.csi.azure.com I0927 06:24:44.026] Driver Version: N/A I0927 06:24:44.026] Git Commit: N/A I0927 06:24:44.026] Go Version: go1.12.1 I0927 06:24:44.026] Platform: linux/amd64 I0927 06:24:44.027] I0927 06:24:44.027] Streaming logs below: I0927 06:24:44.027] I0927 06:24:44.018908 23192 driver.go:80] Enabling controller service capability: CREATE_DELETE_VOLUME I0927 06:24:44.027] I0927 06:24:44.018947 23192 driver.go:80] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0927 06:24:44.028] I0927 06:24:44.018959 23192 driver.go:99] Enabling volume access mode: SINGLE_NODE_WRITER I0927 06:24:44.028] I0927 06:24:44.018965 23192 driver.go:99] Enabling volume access mode: SINGLE_NODE_READER_ONLY I0927 06:24:44.028] I0927 06:24:44.018970 23192 driver.go:99] Enabling volume access mode: MULTI_NODE_READER_ONLY I0927 06:24:44.028] I0927 06:24:44.018976 23192 driver.go:99] Enabling volume access mode: MULTI_NODE_SINGLE_WRITER I0927 06:24:44.028] I0927 06:24:44.018980 23192 driver.go:99] Enabling volume access mode: MULTI_NODE_MULTI_WRITER I0927 06:24:44.028] I0927 06:24:44.019320 23192 server.go:104] Listening for connections on address: &net.UnixAddr{Name:"//tmp/csi-7ec5493f-e0ef-11e9-ae7d-0242c9e6f69d.sock", Net:"unix"} I0927 06:24:44.029] STEP: Building a namespace api object, basename azurefile I0927 06:24:44.643] Sep 27 06:24:44.643: INFO: Found PodSecurityPolicies; assuming PodSecurityPolicy is enabled. I0927 06:24:45.005] Sep 27 06:24:45.005: INFO: Found ClusterRoles; assuming RBAC is enabled. I0927 06:24:45.084] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-3647 I0927 06:24:45.340] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:24:45.416] [BeforeEach] Dynamic Provisioning I0927 06:24:45.417] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I0927 06:24:45.417] [It] should create a deployment object, write and read to it, delete the pod and write and read to it again I0927 06:24:45.417] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:129 I0927 06:24:45.417] STEP: setting up the StorageClass I0927 06:24:45.418] STEP: creating a StorageClass I0927 06:24:45.495] STEP: setting up the PVC I0927 06:24:45.495] STEP: creating a PVC I0927 06:24:45.578] STEP: waiting for PVC to be in phase "Bound" I0927 06:24:45.578] Sep 27 06:24:45.578: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-pn2bc] to have phase Bound I0927 06:24:45.655] Sep 27 06:24:45.655: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:24:47.735] Sep 27 06:24:47.734: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:24:49.813] Sep 27 06:24:49.813: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:24:51.892] Sep 27 06:24:51.891: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:24:53.970] Sep 27 06:24:53.969: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:24:56.048] Sep 27 06:24:56.048: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:24:58.126] Sep 27 06:24:58.126: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:00.205] Sep 27 06:25:00.205: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:02.283] Sep 27 06:25:02.283: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:04.361] Sep 27 06:25:04.360: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:06.439] Sep 27 06:25:06.439: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:08.517] Sep 27 06:25:08.517: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:10.595] Sep 27 06:25:10.595: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:12.673] Sep 27 06:25:12.673: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:14.751] Sep 27 06:25:14.751: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:16.830] Sep 27 06:25:16.829: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:18.908] Sep 27 06:25:18.907: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:20.987] Sep 27 06:25:20.987: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:23.065] Sep 27 06:25:23.065: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:25.143] Sep 27 06:25:25.143: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:27.222] Sep 27 06:25:27.221: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:29.301] Sep 27 06:25:29.300: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:31.378] Sep 27 06:25:31.378: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:33.456] Sep 27 06:25:33.456: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:35.534] Sep 27 06:25:35.534: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:37.612] Sep 27 06:25:37.612: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:39.690] Sep 27 06:25:39.690: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:41.770] Sep 27 06:25:41.768: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:43.846] Sep 27 06:25:43.846: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:45.924] Sep 27 06:25:45.924: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:48.002] Sep 27 06:25:48.002: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:50.080] Sep 27 06:25:50.080: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:52.158] Sep 27 06:25:52.157: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:54.235] Sep 27 06:25:54.235: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:56.313] Sep 27 06:25:56.313: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:25:58.392] Sep 27 06:25:58.391: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:00.470] Sep 27 06:26:00.470: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:02.548] Sep 27 06:26:02.548: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:04.626] Sep 27 06:26:04.626: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:06.704] Sep 27 06:26:06.704: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:08.782] Sep 27 06:26:08.782: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:10.863] Sep 27 06:26:10.863: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:12.941] Sep 27 06:26:12.941: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:15.022] Sep 27 06:26:15.022: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:17.100] Sep 27 06:26:17.100: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:19.178] Sep 27 06:26:19.178: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:21.256] Sep 27 06:26:21.256: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:23.335] Sep 27 06:26:23.335: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:25.413] Sep 27 06:26:25.413: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:27.492] Sep 27 06:26:27.492: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:29.569] Sep 27 06:26:29.569: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:31.648] Sep 27 06:26:31.648: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:33.727] Sep 27 06:26:33.726: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:35.805] Sep 27 06:26:35.805: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:37.884] Sep 27 06:26:37.883: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:39.962] Sep 27 06:26:39.962: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:42.046] Sep 27 06:26:42.046: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:44.124] Sep 27 06:26:44.124: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:46.203] Sep 27 06:26:46.203: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:48.281] Sep 27 06:26:48.281: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:50.360] Sep 27 06:26:50.359: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:52.438] Sep 27 06:26:52.438: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:54.516] Sep 27 06:26:54.516: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:56.594] Sep 27 06:26:56.594: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:26:58.672] Sep 27 06:26:58.672: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:00.750] Sep 27 06:27:00.749: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:02.828] Sep 27 06:27:02.827: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:04.906] Sep 27 06:27:04.905: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:06.983] Sep 27 06:27:06.983: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:09.062] Sep 27 06:27:09.062: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:11.141] Sep 27 06:27:11.140: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:13.219] Sep 27 06:27:13.219: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:15.298] Sep 27 06:27:15.298: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:17.376] Sep 27 06:27:17.376: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:19.454] Sep 27 06:27:19.453: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:21.532] Sep 27 06:27:21.532: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:23.611] Sep 27 06:27:23.610: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:25.689] Sep 27 06:27:25.688: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:27.766] Sep 27 06:27:27.766: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:29.849] Sep 27 06:27:29.848: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:31.926] Sep 27 06:27:31.926: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:34.005] Sep 27 06:27:34.005: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:36.083] Sep 27 06:27:36.083: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:38.161] Sep 27 06:27:38.161: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:40.240] Sep 27 06:27:40.240: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:42.318] Sep 27 06:27:42.318: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:44.397] Sep 27 06:27:44.397: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:46.475] Sep 27 06:27:46.475: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:48.553] Sep 27 06:27:48.553: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:50.631] Sep 27 06:27:50.631: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:52.709] Sep 27 06:27:52.709: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:54.788] Sep 27 06:27:54.787: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:56.868] Sep 27 06:27:56.868: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:27:58.946] Sep 27 06:27:58.946: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:01.024] Sep 27 06:28:01.024: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:03.103] Sep 27 06:28:03.103: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:05.181] Sep 27 06:28:05.181: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:07.260] Sep 27 06:28:07.260: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:09.339] Sep 27 06:28:09.338: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:11.416] Sep 27 06:28:11.416: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:13.495] Sep 27 06:28:13.495: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:15.573] Sep 27 06:28:15.573: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:17.652] Sep 27 06:28:17.651: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:19.730] Sep 27 06:28:19.730: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:21.808] Sep 27 06:28:21.808: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:23.886] Sep 27 06:28:23.886: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:25.964] Sep 27 06:28:25.964: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:28.053] Sep 27 06:28:28.053: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:30.131] Sep 27 06:28:30.131: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:32.210] Sep 27 06:28:32.210: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:34.288] Sep 27 06:28:34.288: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:36.367] Sep 27 06:28:36.366: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:38.445] Sep 27 06:28:38.444: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:40.523] Sep 27 06:28:40.523: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:42.600] Sep 27 06:28:42.600: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:44.678] Sep 27 06:28:44.678: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:46.756] Sep 27 06:28:46.756: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:48.834] Sep 27 06:28:48.834: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:50.913] Sep 27 06:28:50.912: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:52.991] Sep 27 06:28:52.991: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:55.070] Sep 27 06:28:55.070: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:57.148] Sep 27 06:28:57.148: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:28:59.227] Sep 27 06:28:59.226: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:01.305] Sep 27 06:29:01.304: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:03.383] Sep 27 06:29:03.383: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:05.462] Sep 27 06:29:05.462: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:07.540] Sep 27 06:29:07.540: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:09.618] Sep 27 06:29:09.618: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:11.696] Sep 27 06:29:11.696: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:13.774] Sep 27 06:29:13.774: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:15.852] Sep 27 06:29:15.852: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:17.930] Sep 27 06:29:17.930: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:20.009] Sep 27 06:29:20.008: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:22.087] Sep 27 06:29:22.087: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:24.165] Sep 27 06:29:24.165: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:26.243] Sep 27 06:29:26.243: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:28.322] Sep 27 06:29:28.321: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:30.400] Sep 27 06:29:30.400: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:32.484] Sep 27 06:29:32.484: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:34.565] Sep 27 06:29:34.565: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:36.643] Sep 27 06:29:36.642: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:38.721] Sep 27 06:29:38.721: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:40.801] Sep 27 06:29:40.801: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:42.879] Sep 27 06:29:42.879: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:44.958] Sep 27 06:29:44.957: INFO: PersistentVolumeClaim pvc-pn2bc found but phase is Pending instead of Bound. I0927 06:29:46.958] Sep 27 06:29:46.958: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-pn2bc] not all in phase Bound within 5m0s I0927 06:29:46.959] [AfterEach] Dynamic Provisioning I0927 06:29:46.959] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:29:46.959] STEP: Collecting events from namespace "azurefile-3647". I0927 06:29:47.038] STEP: Found 3 events. I0927 06:29:47.039] Sep 27 06:29:47.038: INFO: At 2019-09-27 06:24:45 +0000 UTC - event for pvc-pn2bc: {file.csi.azure.com_csi-azurefile-controller-5f845667ff-696sd_7d0b0c86-e0ef-11e9-94e9-46f08505b930 } Provisioning: External provisioner is provisioning volume for claim "azurefile-3647/pvc-pn2bc" I0927 06:29:47.039] Sep 27 06:29:47.038: INFO: At 2019-09-27 06:24:45 +0000 UTC - event for pvc-pn2bc: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator I0927 06:29:47.040] Sep 27 06:29:47.038: INFO: At 2019-09-27 06:24:46 +0000 UTC - event for pvc-pn2bc: {file.csi.azure.com_csi-azurefile-controller-5f845667ff-696sd_7d0b0c86-e0ef-11e9-94e9-46f08505b930 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-3647-file.csi.azure.com-dynamic-sc-9qrw5": rpc error: code = Unknown desc = failed to create file share(pvc-15b812af-a7c6-4df7-ad99-8dfb93a124a5) on account() type(Standard_LRS) rg() location() size(10), error: could not get storage key for storage account : could not list storage accounts for account type Standard_LRS: storage.AccountsClient#ListByResourceGroup: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code="ResourceGroupNotFound" Message="Resource group 'kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d' could not be found." I0927 06:29:47.282] Sep 27 06:29:47.281: INFO: POD NODE PHASE GRACE CONDITIONS I0927 06:29:47.282] Sep 27 06:29:47.281: INFO: azure-ip-masq-agent-dcc9z k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:30 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:30 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.283] Sep 27 06:29:47.281: INFO: azure-ip-masq-agent-np8bd k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:01 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:11 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:11 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.283] Sep 27 06:29:47.281: INFO: azure-ip-masq-agent-twpx4 k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:02 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:02 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.284] Sep 27 06:29:47.282: INFO: blobfuse-flexvol-installer-q2dbr k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:18 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:18 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.284] Sep 27 06:29:47.282: INFO: blobfuse-flexvol-installer-tf52f k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:00 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:23 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:23 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.284] Sep 27 06:29:47.282: INFO: cloud-controller-manager-k8s-master-10768025-0 k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:38 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:38 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC }] I0927 06:29:47.285] Sep 27 06:29:47.282: INFO: coredns-7f68dcdbdb-r6zvs k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:37 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:37 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.285] Sep 27 06:29:47.282: INFO: csi-azurefile-controller-5f845667ff-696sd k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:23:52 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:24:41 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:24:41 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:23:52 +0000 UTC }] I0927 06:29:47.286] Sep 27 06:29:47.282: INFO: csi-azurefile-node-7bvhj k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:23:52 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:24:24 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:24:24 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:23:52 +0000 UTC }] I0927 06:29:47.286] Sep 27 06:29:47.282: INFO: csi-azurefile-node-qkh7d k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:23:52 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:24:29 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:24:29 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:23:52 +0000 UTC }] I0927 06:29:47.287] Sep 27 06:29:47.282: INFO: keyvault-flexvolume-2xv9z k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:01 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:17 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:17 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.287] Sep 27 06:29:47.282: INFO: keyvault-flexvolume-rvr2z k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:31 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:31 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.288] Sep 27 06:29:47.282: INFO: kube-addon-manager-k8s-master-10768025-0 k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:42 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:42 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC }] I0927 06:29:47.288] Sep 27 06:29:47.282: INFO: kube-apiserver-k8s-master-10768025-0 k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:25 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:25 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC }] I0927 06:29:47.289] Sep 27 06:29:47.282: INFO: kube-controller-manager-k8s-master-10768025-0 k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:25 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:25 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:21 +0000 UTC }] I0927 06:29:47.289] Sep 27 06:29:47.282: INFO: kube-proxy-9xq7r k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:01 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:01 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC }] I0927 06:29:47.290] Sep 27 06:29:47.282: INFO: kube-proxy-b4tmr k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:01 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:03 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:03 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.290] Sep 27 06:29:47.282: INFO: kube-proxy-j8mxv k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:59 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:59 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC }] I0927 06:29:47.290] Sep 27 06:29:47.282: INFO: kube-scheduler-k8s-master-10768025-0 k8s-master-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:45 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:45 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:45 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:45 +0000 UTC }] I0927 06:29:47.291] Sep 27 06:29:47.282: INFO: kubernetes-dashboard-66dd8b8df7-jh4n5 k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:48 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:48 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC }] I0927 06:29:47.291] Sep 27 06:29:47.282: INFO: metrics-server-864ffbc5c-d6dvl k8s-agentpool1-10768025-1 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:39 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:39 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:56 +0000 UTC }] I0927 06:29:47.292] Sep 27 06:29:47.282: INFO: tiller-deploy-54c96cb5df-n8lhd k8s-agentpool1-10768025-0 Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:01 +0000 UTC } {Ready True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:35 +0000 UTC } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:22:35 +0000 UTC } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2019-09-27 06:21:57 +0000 UTC }] I0927 06:29:47.292] Sep 27 06:29:47.282: INFO: I0927 06:29:47.361] Sep 27 06:29:47.360: INFO: I0927 06:29:47.361] Logging node info for node k8s-agentpool1-10768025-0 I0927 06:29:47.442] Sep 27 06:29:47.438: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool1-10768025-0,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool1-10768025-0,UID:624463bb-773d-46a4-8a48-d711afb03759,ResourceVersion:1672,Generation:0,CreationTimestamp:2019-09-27 06:21:34 +0000 UTC,DeletionTimestamp:,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool1,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: 1,kubernetes.azure.com/cluster: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool1-10768025-0,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"file.csi.azure.com":"k8s-agentpool1-10768025-0"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d/providers/Microsoft.Compute/virtualMachines/k8s-agentpool1-10768025-0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{cpu: {{4 0} {} 4 DecimalSI},ephemeral-storage: {{31158935552 0} {} BinarySI},hugepages-1Gi: {{0 0} {} 0 DecimalSI},hugepages-2Mi: {{0 0} {} 0 DecimalSI},memory: {{16797073408 0} {} BinarySI},pods: {{110 0} {} 110 DecimalSI},},Allocatable:ResourceList{cpu: {{4 0} {} 4 DecimalSI},ephemeral-storage: {{28043041951 0} {} 28043041951 DecimalSI},hugepages-1Gi: {{0 0} {} 0 DecimalSI},hugepages-2Mi: {{0 0} {} 0 DecimalSI},memory: {{16010641408 0} {} BinarySI},pods: {{110 0} {} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-09-27 06:22:10 +0000 UTC 2019-09-27 06:22:10 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-09-27 06:28:55 +0000 UTC 2019-09-27 06:21:25 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-09-27 06:28:55 +0000 UTC 2019-09-27 06:21:25 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-09-27 06:28:55 +0000 UTC 2019-09-27 06:21:25 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-09-27 06:28:55 +0000 UTC 2019-09-27 06:21:53 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.240.0.4} {Hostname k8s-agentpool1-10768025-0}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:2b6c53cba2ab440c923c34ad43c7edcb,SystemUUID:FF623BAE-E8CF-2246-A38F-A561E9F3C424,BootID:36e93bc4-a2f3-453b-9629-58769009c721,KernelVersion:4.15.0-1057-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azurefile-csi@sha256:46835feeb296dfcb3aa18798c6c5646c0cd1e19ac4f595a2a84a17bcc405087d k8sprowinternal.azurecr.io/azurefile-csi:v0.4.0] 246132974} {[gcr.io/kubernetes-helm/tiller@sha256:f6d8f4ab9ba993b5f5b60a6edafe86352eabe474ffeb84cb6c79b8866dce45d1 gcr.io/kubernetes-helm/tiller:v2.11.0] 71821984} {[quay.io/k8scsi/csi-attacher@sha256:6425af42299ba211de685a94953a5c4c6fcbfd2494e445437dd9ebd70b28bf8a quay.io/k8scsi/csi-attacher:v1.0.1] 50168619} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[quay.io/k8scsi/csi-provisioner@sha256:7d7d832832b536f32e899669a32d4fb75ab972da20c21a2bd6043eb498cf58e8 quay.io/k8scsi/csi-provisioner:v1.0.1] 47974767} {[quay.io/k8scsi/csi-cluster-driver-registrar@sha256:fafd75ae5442f192cfa8c2e792903aee30d5884b62e802e4464b0a895d21e3ef quay.io/k8scsi/csi-cluster-driver-registrar:v1.0.1] 45874691} {[quay.io/k8scsi/csi-snapshotter@sha256:a49e0da1af6f2bf717e41ba1eee8b5e6a1cbd66a709dd92cc43fe475fe2589eb quay.io/k8scsi/csi-snapshotter:v1.1.0] 44325352} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[quay.io/k8scsi/livenessprobe@sha256:dde617756e0f602adc566ab71fd885f1dad451ad3fb063ac991c95a2ff47aea5 quay.io/k8scsi/livenessprobe:v1.1.0] 14967303} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} I0927 06:29:47.442] Sep 27 06:29:47.439: INFO: I0927 06:29:47.442] Logging kubelet events for node k8s-agentpool1-10768025-0 I0927 06:29:47.520] Sep 27 06:29:47.520: INFO: I0927 06:29:47.520] Logging pods the kubelet thinks is on node k8s-agentpool1-10768025-0 I0927 06:29:47.631] Sep 27 06:29:47.631: INFO: tiller-deploy-54c96cb5df-n8lhd started at 2019-09-27 06:22:01 +0000 UTC (0+1 container statuses recorded) I0927 06:29:47.632] Sep 27 06:29:47.631: INFO: Container tiller ready: true, restart count 0 I0927 06:29:47.632] Sep 27 06:29:47.631: INFO: csi-azurefile-node-qkh7d started at 2019-09-27 06:23:52 +0000 UTC (0+3 container statuses recorded) I0927 06:29:47.632] Sep 27 06:29:47.631: INFO: Container azurefile ready: true, restart count 0 I0927 06:29:47.632] Sep 27 06:29:47.631: INFO: Container liveness-probe ready: true, restart count 0 I0927 06:29:47.632] Sep 27 06:29:47.631: INFO: Container node-driver-registrar ready: true, restart count 0 I0927 06:29:47.633] Sep 27 06:29:47.631: INFO: csi-azurefile-controller-5f845667ff-696sd started at 2019-09-27 06:23:52 +0000 UTC (0+6 container statuses recorded) I0927 06:29:47.633] Sep 27 06:29:47.631: INFO: Container azurefile ready: true, restart count 0 I0927 06:29:47.633] Sep 27 06:29:47.631: INFO: Container cluster-driver-registrar ready: true, restart count 0 I0927 06:29:47.633] Sep 27 06:29:47.631: INFO: Container csi-attacher ready: true, restart count 0 I0927 06:29:47.634] Sep 27 06:29:47.631: INFO: Container csi-provisioner ready: true, restart count 0 I0927 06:29:47.634] Sep 27 06:29:47.631: INFO: Container csi-snapshotter ready: true, restart count 0 I0927 06:29:47.634] Sep 27 06:29:47.631: INFO: Container liveness-probe ready: true, restart count 0 I0927 06:29:47.634] Sep 27 06:29:47.631: INFO: blobfuse-flexvol-installer-tf52f started at 2019-09-27 06:22:00 +0000 UTC (0+1 container statuses recorded) I0927 06:29:47.634] Sep 27 06:29:47.631: INFO: Container blobfuse-flexvol-installer ready: true, restart count 0 I0927 06:29:47.635] Sep 27 06:29:47.631: INFO: azure-ip-masq-agent-np8bd started at 2019-09-27 06:22:01 +0000 UTC (0+1 container statuses recorded) I0927 06:29:47.635] Sep 27 06:29:47.631: INFO: Container azure-ip-masq-agent ready: true, restart count 0 I0927 06:29:47.635] Sep 27 06:29:47.631: INFO: keyvault-flexvolume-2xv9z started at 2019-09-27 06:22:01 +0000 UTC (0+1 container statuses recorded) I0927 06:29:47.635] Sep 27 06:29:47.631: INFO: Container keyvault-flexvolume ready: true, restart count 0 I0927 06:29:47.635] Sep 27 06:29:47.631: INFO: kube-proxy-b4tmr started at 2019-09-27 06:22:01 +0000 UTC (0+1 container statuses recorded) I0927 06:29:47.636] Sep 27 06:29:47.631: INFO: Container kube-proxy ready: true, restart count 0 I0927 06:29:47.709] W0927 06:29:47.709471 23192 metrics_grabber.go:79] Master node is not registered. Grabbing metrics from Scheduler, ControllerManager and ClusterAutoscaler is disabled. I0927 06:29:47.883] Sep 27 06:29:47.881: INFO: I0927 06:29:47.883] Latency metrics for node k8s-agentpool1-10768025-0 I0927 06:29:47.883] Sep 27 06:29:47.881: INFO: I0927 06:29:47.883] Logging node info for node k8s-agentpool1-10768025-1 I0927 06:29:47.962] Sep 27 06:29:47.959: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool1-10768025-1,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool1-10768025-1,UID:228e5346-db61-43cd-8062-5455e5369115,ResourceVersion:1752,Generation:0,CreationTimestamp:2019-09-27 06:21:34 +0000 UTC,DeletionTimestamp:,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool1,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: 0,kubernetes.azure.com/cluster: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool1-10768025-1,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"file.csi.azure.com":"k8s-agentpool1-10768025-1"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.2.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d/providers/Microsoft.Compute/virtualMachines/k8s-agentpool1-10768025-1,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{cpu: {{4 0} {} 4 DecimalSI},ephemeral-storage: {{31158935552 0} {} BinarySI},hugepages-1Gi: {{0 0} {} 0 DecimalSI},hugepages-2Mi: {{0 0} {} 0 DecimalSI},memory: {{16797073408 0} {} BinarySI},pods: {{110 0} {} 110 DecimalSI},},Allocatable:ResourceList{cpu: {{4 0} {} 4 DecimalSI},ephemeral-storage: {{28043041951 0} {} 28043041951 DecimalSI},hugepages-1Gi: {{0 0} {} 0 DecimalSI},hugepages-2Mi: {{0 0} {} 0 DecimalSI},memory: {{16010641408 0} {} BinarySI},pods: {{110 0} {} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-09-27 06:22:21 +0000 UTC 2019-09-27 06:22:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-09-27 06:29:35 +0000 UTC 2019-09-27 06:21:26 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-09-27 06:29:35 +0000 UTC 2019-09-27 06:21:26 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-09-27 06:29:35 +0000 UTC 2019-09-27 06:21:26 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-09-27 06:29:35 +0000 UTC 2019-09-27 06:21:53 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.240.0.5} {Hostname k8s-agentpool1-10768025-1}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:9ff95624538c4f0c8d0ed73a31b9a5f6,SystemUUID:AB65A36A-2137-5F44-AC1E-0268D872DCC3,BootID:1c517a69-c19d-4f17-89ea-31ec361a2071,KernelVersion:4.15.0-1057-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azurefile-csi@sha256:46835feeb296dfcb3aa18798c6c5646c0cd1e19ac4f595a2a84a17bcc405087d k8sprowinternal.azurecr.io/azurefile-csi:v0.4.0] 246132974} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[k8s.gcr.io/coredns@sha256:e83beb5e43f8513fa735e77ffc5859640baea30a882a11cc75c4c3244a737d3c k8s.gcr.io/coredns:1.5.0] 42488424} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} I0927 06:29:47.962] Sep 27 06:29:47.959: INFO: I0927 06:29:47.962] Logging kubelet events for node k8s-agentpool1-10768025-1 I0927 06:29:48.040] Sep 27 06:29:48.040: INFO: I0927 06:29:48.040] Logging pods the kubelet thinks is on node k8s-agentpool1-10768025-1 I0927 06:29:48.146] Sep 27 06:29:48.145: INFO: coredns-7f68dcdbdb-r6zvs started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.146] Sep 27 06:29:48.145: INFO: Container coredns ready: true, restart count 0 I0927 06:29:48.146] Sep 27 06:29:48.145: INFO: azure-ip-masq-agent-dcc9z started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.146] Sep 27 06:29:48.145: INFO: Container azure-ip-masq-agent ready: true, restart count 0 I0927 06:29:48.146] Sep 27 06:29:48.145: INFO: keyvault-flexvolume-rvr2z started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.147] Sep 27 06:29:48.145: INFO: Container keyvault-flexvolume ready: true, restart count 0 I0927 06:29:48.147] Sep 27 06:29:48.145: INFO: metrics-server-864ffbc5c-d6dvl started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.147] Sep 27 06:29:48.145: INFO: Container metrics-server ready: true, restart count 1 I0927 06:29:48.147] Sep 27 06:29:48.145: INFO: kube-proxy-9xq7r started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.147] Sep 27 06:29:48.145: INFO: Container kube-proxy ready: true, restart count 0 I0927 06:29:48.147] Sep 27 06:29:48.145: INFO: kubernetes-dashboard-66dd8b8df7-jh4n5 started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.148] Sep 27 06:29:48.145: INFO: Container kubernetes-dashboard ready: true, restart count 1 I0927 06:29:48.148] Sep 27 06:29:48.145: INFO: csi-azurefile-node-7bvhj started at 2019-09-27 06:23:52 +0000 UTC (0+3 container statuses recorded) I0927 06:29:48.148] Sep 27 06:29:48.145: INFO: Container azurefile ready: true, restart count 0 I0927 06:29:48.148] Sep 27 06:29:48.145: INFO: Container liveness-probe ready: true, restart count 0 I0927 06:29:48.148] Sep 27 06:29:48.145: INFO: Container node-driver-registrar ready: true, restart count 0 I0927 06:29:48.148] Sep 27 06:29:48.145: INFO: blobfuse-flexvol-installer-q2dbr started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.149] Sep 27 06:29:48.145: INFO: Container blobfuse-flexvol-installer ready: true, restart count 0 I0927 06:29:48.225] W0927 06:29:48.224859 23192 metrics_grabber.go:79] Master node is not registered. Grabbing metrics from Scheduler, ControllerManager and ClusterAutoscaler is disabled. I0927 06:29:48.407] Sep 27 06:29:48.407: INFO: I0927 06:29:48.408] Latency metrics for node k8s-agentpool1-10768025-1 I0927 06:29:48.408] Sep 27 06:29:48.407: INFO: I0927 06:29:48.408] Logging node info for node k8s-master-10768025-0 I0927 06:29:48.488] Sep 27 06:29:48.485: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-master-10768025-0,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-master-10768025-0,UID:170d5547-da4c-49a1-9ef5-3ed52a739d84,ResourceVersion:1732,Generation:0,CreationTimestamp:2019-09-27 06:21:34 +0000 UTC,DeletionTimestamp:,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_DS2_v2,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: 0,kubernetes.azure.com/cluster: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d,kubernetes.azure.com/role: master,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-master-10768025-0,kubernetes.io/os: linux,kubernetes.io/role: master,node-role.kubernetes.io/master: ,},Annotations:map[string]string{node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.1.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d/providers/Microsoft.Compute/virtualMachines/k8s-master-10768025-0,Unschedulable:false,Taints:[{node-role.kubernetes.io/master true NoSchedule }],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{cpu: {{2 0} {} 2 DecimalSI},ephemeral-storage: {{31158935552 0} {} BinarySI},hugepages-1Gi: {{0 0} {} 0 DecimalSI},hugepages-2Mi: {{0 0} {} 0 DecimalSI},memory: {{7284391936 0} {} BinarySI},pods: {{110 0} {} 110 DecimalSI},},Allocatable:ResourceList{cpu: {{2 0} {} 2 DecimalSI},ephemeral-storage: {{28043041951 0} {} 28043041951 DecimalSI},hugepages-1Gi: {{0 0} {} 0 DecimalSI},hugepages-2Mi: {{0 0} {} 0 DecimalSI},memory: {{6497959936 0} {} BinarySI},pods: {{110 0} {} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-09-27 06:22:24 +0000 UTC 2019-09-27 06:22:24 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-09-27 06:29:25 +0000 UTC 2019-09-27 06:21:27 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-09-27 06:29:25 +0000 UTC 2019-09-27 06:21:27 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-09-27 06:29:25 +0000 UTC 2019-09-27 06:21:27 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-09-27 06:29:25 +0000 UTC 2019-09-27 06:21:53 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{Hostname k8s-master-10768025-0} {InternalIP 10.240.255.5}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:2b18c378da164589be2a227d84506dfc,SystemUUID:06110EFC-059D-FC44-A178-B3A35D82935E,BootID:7fad807c-3d68-44b8-8fe0-0cff91ececa4,KernelVersion:4.15.0-1057-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[gcrio.azureedge.net/google_containers/cloud-controller-manager-amd64@sha256:d2397a13afbf962153355d029a62c7b7175c6c525faadce790671280475f5c02 gcrio.azureedge.net/google_containers/cloud-controller-manager-amd64:v1.15.0] 142865982} {[k8s.gcr.io/kube-addon-manager-amd64@sha256:382c220b3531d9f95bf316a16b7282cc2ef929cd8a89a9dd3f5933edafc41a8e k8s.gcr.io/kube-addon-manager-amd64:v9.0.1] 83076194} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} I0927 06:29:48.488] Sep 27 06:29:48.485: INFO: I0927 06:29:48.488] Logging kubelet events for node k8s-master-10768025-0 I0927 06:29:48.567] Sep 27 06:29:48.567: INFO: I0927 06:29:48.567] Logging pods the kubelet thinks is on node k8s-master-10768025-0 I0927 06:29:48.669] Sep 27 06:29:48.669: INFO: cloud-controller-manager-k8s-master-10768025-0 started at 2019-09-27 06:21:21 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.669] Sep 27 06:29:48.669: INFO: Container cloud-controller-manager ready: true, restart count 0 I0927 06:29:48.670] Sep 27 06:29:48.669: INFO: kube-addon-manager-k8s-master-10768025-0 started at 2019-09-27 06:21:21 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.670] Sep 27 06:29:48.669: INFO: Container kube-addon-manager ready: true, restart count 0 I0927 06:29:48.670] Sep 27 06:29:48.669: INFO: kube-apiserver-k8s-master-10768025-0 started at 2019-09-27 06:21:21 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.670] Sep 27 06:29:48.669: INFO: Container kube-apiserver ready: true, restart count 0 I0927 06:29:48.670] Sep 27 06:29:48.669: INFO: azure-ip-masq-agent-twpx4 started at 2019-09-27 06:21:56 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.671] Sep 27 06:29:48.669: INFO: Container azure-ip-masq-agent ready: true, restart count 0 I0927 06:29:48.671] Sep 27 06:29:48.669: INFO: kube-proxy-j8mxv started at 2019-09-27 06:21:57 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.671] Sep 27 06:29:48.669: INFO: Container kube-proxy ready: true, restart count 0 I0927 06:29:48.671] Sep 27 06:29:48.669: INFO: kube-controller-manager-k8s-master-10768025-0 started at 2019-09-27 06:21:21 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.672] Sep 27 06:29:48.669: INFO: Container kube-controller-manager ready: true, restart count 0 I0927 06:29:48.672] Sep 27 06:29:48.669: INFO: kube-scheduler-k8s-master-10768025-0 started at 2019-09-27 06:22:45 +0000 UTC (0+1 container statuses recorded) I0927 06:29:48.672] Sep 27 06:29:48.669: INFO: Container kube-scheduler ready: true, restart count 0 I0927 06:29:48.747] W0927 06:29:48.747008 23192 metrics_grabber.go:79] Master node is not registered. Grabbing metrics from Scheduler, ControllerManager and ClusterAutoscaler is disabled. I0927 06:29:48.925] Sep 27 06:29:48.925: INFO: I0927 06:29:48.926] Latency metrics for node k8s-master-10768025-0 I0927 06:29:48.926] Sep 27 06:29:48.925: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:29:49.003] STEP: Destroying namespace "azurefile-3647" for this suite. I0927 06:30:03.239] Sep 27 06:30:03.239: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:30:06.194] Sep 27 06:30:06.194: INFO: namespace azurefile-3647 deletion completed in 17.190844786s I0927 06:30:06.195] I0927 06:30:06.195] • Failure [322.177 seconds] I0927 06:30:06.195] Dynamic Provisioning I0927 06:30:06.195] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I0927 06:30:06.196] should create a deployment object, write and read to it, delete the pod and write and read to it again [It] I0927 06:30:06.196] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:129 I0927 06:30:06.196] I0927 06:30:06.196] Expected error: I0927 06:30:06.196] <*errors.errorString | 0xc000876ba0>: { I0927 06:30:06.197] s: "PersistentVolumeClaims [pvc-pn2bc] not all in phase Bound within 5m0s", I0927 06:30:06.197] } I0927 06:30:06.197] PersistentVolumeClaims [pvc-pn2bc] not all in phase Bound within 5m0s I0927 06:30:06.197] not to have occurred I0927 06:30:06.197] I0927 06:30:06.198] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:272 I0927 06:30:06.198] ------------------------------ I0927 06:30:06.198] Dynamic Provisioning I0927 06:30:06.198] [env] should retain PV with reclaimPolicy "Retain" I0927 06:30:06.198] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:170 I0927 06:30:06.199] [BeforeEach] Dynamic Provisioning I0927 06:30:06.199] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:30:06.199] STEP: Creating a kubernetes client I0927 06:30:06.199] Sep 27 06:30:06.194: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:30:06.200] STEP: Building a namespace api object, basename azurefile I0927 06:30:06.430] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-276 I0927 06:30:06.686] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:30:06.763] [BeforeEach] Dynamic Provisioning I0927 06:30:06.763] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I0927 06:30:06.763] [It] [env] should retain PV with reclaimPolicy "Retain" I0927 06:30:06.763] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:170 I0927 06:30:06.764] STEP: setting up the StorageClass I0927 06:30:06.764] STEP: creating a StorageClass I0927 06:30:06.841] STEP: setting up the PVC and PV I0927 06:30:06.841] STEP: creating a PVC I0927 06:30:06.921] STEP: waiting for PVC to be in phase "Bound" I0927 06:30:06.922] Sep 27 06:30:06.921: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-fnkql] to have phase Bound I0927 06:30:06.999] Sep 27 06:30:06.998: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:09.077] Sep 27 06:30:09.077: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:11.155] Sep 27 06:30:11.154: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:13.233] Sep 27 06:30:13.233: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:15.312] Sep 27 06:30:15.311: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:17.392] Sep 27 06:30:17.392: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:19.470] Sep 27 06:30:19.470: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:21.549] Sep 27 06:30:21.548: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:23.627] Sep 27 06:30:23.627: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:25.705] Sep 27 06:30:25.705: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:27.784] Sep 27 06:30:27.783: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:29.862] Sep 27 06:30:29.861: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:31.940] Sep 27 06:30:31.939: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:34.018] Sep 27 06:30:34.018: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:36.096] Sep 27 06:30:36.096: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:38.174] Sep 27 06:30:38.174: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:40.252] Sep 27 06:30:40.252: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:42.330] Sep 27 06:30:42.330: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:44.408] Sep 27 06:30:44.408: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:46.487] Sep 27 06:30:46.487: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:48.565] Sep 27 06:30:48.565: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:50.643] Sep 27 06:30:50.643: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:52.721] Sep 27 06:30:52.721: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:54.799] Sep 27 06:30:54.799: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:56.877] Sep 27 06:30:56.877: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:30:58.955] Sep 27 06:30:58.955: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:01.033] Sep 27 06:31:01.032: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:03.110] Sep 27 06:31:03.110: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:05.188] Sep 27 06:31:05.188: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:07.266] Sep 27 06:31:07.266: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:09.345] Sep 27 06:31:09.344: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:11.423] Sep 27 06:31:11.423: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:13.501] Sep 27 06:31:13.501: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:15.579] Sep 27 06:31:15.579: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:17.657] Sep 27 06:31:17.657: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:19.736] Sep 27 06:31:19.735: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:21.814] Sep 27 06:31:21.814: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:23.892] Sep 27 06:31:23.892: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:25.970] Sep 27 06:31:25.970: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:28.049] Sep 27 06:31:28.048: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:30.127] Sep 27 06:31:30.127: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:32.205] Sep 27 06:31:32.205: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:34.283] Sep 27 06:31:34.283: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:36.362] Sep 27 06:31:36.362: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:38.440] Sep 27 06:31:38.440: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:40.518] Sep 27 06:31:40.518: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:42.597] Sep 27 06:31:42.597: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:44.675] Sep 27 06:31:44.675: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:46.753] Sep 27 06:31:46.753: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:48.832] Sep 27 06:31:48.831: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:50.910] Sep 27 06:31:50.910: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:52.989] Sep 27 06:31:52.988: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:55.067] Sep 27 06:31:55.066: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:57.150] Sep 27 06:31:57.149: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:31:59.233] Sep 27 06:31:59.232: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:01.311] Sep 27 06:32:01.311: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:03.390] Sep 27 06:32:03.389: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:05.468] Sep 27 06:32:05.468: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:07.546] Sep 27 06:32:07.546: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:09.624] Sep 27 06:32:09.624: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:11.703] Sep 27 06:32:11.702: INFO: PersistentVolumeClaim pvc-fnkql found but phase is Pending instead of Bound. I0927 06:32:13.781] Sep 27 06:32:13.781: INFO: PersistentVolumeClaim pvc-fnkql found and phase=Bound (2m6.859388074s) I0927 06:32:13.781] STEP: checking the PVC I0927 06:32:13.859] STEP: validating provisioned PV I0927 06:32:13.938] STEP: checking the PV I0927 06:32:13.938] Sep 27 06:32:13.938: INFO: deleting PVC "azurefile-276"/"pvc-fnkql" I0927 06:32:13.938] Sep 27 06:32:13.938: INFO: Deleting PersistentVolumeClaim "pvc-fnkql" I0927 06:32:14.017] Sep 27 06:32:14.017: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-276 to be removed I0927 06:32:14.094] Sep 27 06:32:14.094: INFO: Claim "azurefile-276" in namespace "pvc-fnkql" doesn't exist in the system I0927 06:32:14.095] Sep 27 06:32:14.094: INFO: Waiting up to 10m0s for PersistentVolume pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd to have phase Released I0927 06:32:14.172] Sep 27 06:32:14.172: INFO: PersistentVolume pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd found and phase=Released (77.814361ms) I0927 06:32:14.172] STEP: deleting PV "pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd" I0927 06:32:14.172] Sep 27 06:32:14.172: INFO: Deleting PersistentVolume "pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd" I0927 06:32:14.251] STEP: waiting for claim's PV "pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd" to be deleted I0927 06:32:14.252] Sep 27 06:32:14.251: INFO: Waiting up to 10m0s for PersistentVolume pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd to get deleted I0927 06:32:14.329] Sep 27 06:32:14.328: INFO: PersistentVolume pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd was removed I0927 06:32:14.329] STEP: deleting azurefile volume "#f7de16c83e0f011e9a9ed46#pvc-05346de7-70e1-4c85-8779-71bdbf10cfbd" I0927 06:32:15.522] [AfterEach] Dynamic Provisioning I0927 06:32:15.522] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:32:15.523] Sep 27 06:32:15.522: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:32:15.600] STEP: Destroying namespace "azurefile-276" for this suite. I0927 06:32:21.835] Sep 27 06:32:21.835: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:32:24.785] Sep 27 06:32:24.785: INFO: namespace azurefile-276 deletion completed in 9.184630998s I0927 06:32:24.785] I0927 06:32:24.785] • [SLOW TEST:138.590 seconds] I0927 06:32:24.785] Dynamic Provisioning I0927 06:32:24.785] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I0927 06:32:24.786] [env] should retain PV with reclaimPolicy "Retain" I0927 06:32:24.786] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:170 I0927 06:32:24.786] ------------------------------ I0927 06:32:24.786] Dynamic Provisioning I0927 06:32:24.786] should create a volume on demand and mount it as readOnly in a pod I0927 06:32:24.786] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:105 I0927 06:32:24.787] [BeforeEach] Dynamic Provisioning I0927 06:32:24.787] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:32:24.787] STEP: Creating a kubernetes client I0927 06:32:24.787] Sep 27 06:32:24.785: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:32:24.787] STEP: Building a namespace api object, basename azurefile I0927 06:32:25.019] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-2667 I0927 06:32:25.274] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:32:25.351] [BeforeEach] Dynamic Provisioning I0927 06:32:25.352] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I0927 06:32:25.352] [It] should create a volume on demand and mount it as readOnly in a pod I0927 06:32:25.352] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:105 I0927 06:32:25.352] STEP: setting up the StorageClass I0927 06:32:25.353] STEP: creating a StorageClass I0927 06:32:25.430] STEP: setting up the PVC and PV I0927 06:32:25.430] STEP: creating a PVC I0927 06:32:25.512] STEP: waiting for PVC to be in phase "Bound" I0927 06:32:25.512] Sep 27 06:32:25.512: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-vw8qd] to have phase Bound I0927 06:32:25.589] Sep 27 06:32:25.589: INFO: PersistentVolumeClaim pvc-vw8qd found but phase is Pending instead of Bound. I0927 06:32:27.668] Sep 27 06:32:27.667: INFO: PersistentVolumeClaim pvc-vw8qd found and phase=Bound (2.155349405s) I0927 06:32:27.668] STEP: checking the PVC I0927 06:32:27.745] STEP: validating provisioned PV I0927 06:32:27.823] STEP: checking the PV I0927 06:32:27.823] STEP: deploying the pod I0927 06:32:27.904] STEP: checking that the pods command exits with an error I0927 06:32:27.904] Sep 27 06:32:27.904: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-cqd9c" in namespace "azurefile-2667" to be "Error status code" I0927 06:32:27.981] Sep 27 06:32:27.981: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 77.153551ms I0927 06:32:30.059] Sep 27 06:32:30.059: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 2.155440788s I0927 06:32:32.138] Sep 27 06:32:32.137: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 4.233751911s I0927 06:32:34.218] Sep 27 06:32:34.218: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 6.313954639s I0927 06:32:36.296] Sep 27 06:32:36.296: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 8.392064432s I0927 06:32:38.376] Sep 27 06:32:38.375: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 10.471416024s I0927 06:32:40.454] Sep 27 06:32:40.454: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 12.549771293s I0927 06:32:42.532] Sep 27 06:32:42.532: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 14.628225048s I0927 06:32:44.612] Sep 27 06:32:44.612: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 16.708296106s I0927 06:32:46.691] Sep 27 06:32:46.690: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Pending", Reason="", readiness=false. Elapsed: 18.786542233s I0927 06:32:48.769] Sep 27 06:32:48.769: INFO: Pod "azurefile-volume-tester-cqd9c": Phase="Failed", Reason="", readiness=false. Elapsed: 20.865445152s I0927 06:32:48.770] STEP: Saw pod failure I0927 06:32:48.770] Sep 27 06:32:48.769: INFO: Pod "azurefile-volume-tester-cqd9c" satisfied condition "Error status code" I0927 06:32:48.770] STEP: checking that pod logs contain expected message I0927 06:32:48.866] Sep 27 06:32:48.866: INFO: deleting Pod "azurefile-2667"/"azurefile-volume-tester-cqd9c" I0927 06:32:48.948] Sep 27 06:32:48.948: INFO: Pod azurefile-volume-tester-cqd9c has the following logs: touch: /mnt/test-1/data: Read-only file system I0927 06:32:48.948] I0927 06:32:48.948] STEP: Deleting pod azurefile-volume-tester-cqd9c in namespace azurefile-2667 I0927 06:32:49.032] Sep 27 06:32:49.032: INFO: deleting PVC "azurefile-2667"/"pvc-vw8qd" I0927 06:32:49.032] Sep 27 06:32:49.032: INFO: Deleting PersistentVolumeClaim "pvc-vw8qd" I0927 06:32:49.111] STEP: waiting for claim's PV "pvc-65cc3051-e3ba-4c1e-88f5-ba458dcc8d72" to be deleted I0927 06:32:49.111] Sep 27 06:32:49.111: INFO: Waiting up to 10m0s for PersistentVolume pvc-65cc3051-e3ba-4c1e-88f5-ba458dcc8d72 to get deleted I0927 06:32:49.189] Sep 27 06:32:49.189: INFO: PersistentVolume pvc-65cc3051-e3ba-4c1e-88f5-ba458dcc8d72 found and phase=Released (78.022155ms) I0927 06:32:54.268] Sep 27 06:32:54.268: INFO: PersistentVolume pvc-65cc3051-e3ba-4c1e-88f5-ba458dcc8d72 was removed I0927 06:32:54.268] Sep 27 06:32:54.268: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2667 to be removed I0927 06:32:54.345] Sep 27 06:32:54.345: INFO: Claim "azurefile-2667" in namespace "pvc-vw8qd" doesn't exist in the system I0927 06:32:54.345] Sep 27 06:32:54.345: INFO: deleting StorageClass azurefile-2667-file.csi.azure.com-dynamic-sc-2k4k2 I0927 06:32:54.425] [AfterEach] Dynamic Provisioning I0927 06:32:54.426] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:32:54.426] Sep 27 06:32:54.425: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:32:54.578] STEP: Destroying namespace "azurefile-2667" for this suite. I0927 06:33:00.820] Sep 27 06:33:00.820: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:33:03.771] Sep 27 06:33:03.770: INFO: namespace azurefile-2667 deletion completed in 9.19247634s I0927 06:33:03.771] I0927 06:33:03.771] • [SLOW TEST:38.986 seconds] I0927 06:33:03.772] Dynamic Provisioning I0927 06:33:03.772] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I0927 06:33:03.772] should create a volume on demand and mount it as readOnly in a pod I0927 06:33:03.772] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:105 I0927 06:33:03.773] ------------------------------ I0927 06:33:03.773] Dynamic Provisioning I0927 06:33:03.773] should delete PV with reclaimPolicy "Delete" I0927 06:33:03.773] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:154 I0927 06:33:03.773] [BeforeEach] Dynamic Provisioning I0927 06:33:03.773] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:33:03.773] STEP: Creating a kubernetes client I0927 06:33:03.774] Sep 27 06:33:03.771: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:33:03.774] STEP: Building a namespace api object, basename azurefile I0927 06:33:04.006] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-6776 I0927 06:33:04.263] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:33:04.340] [BeforeEach] Dynamic Provisioning I0927 06:33:04.340] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I0927 06:33:04.340] [It] should delete PV with reclaimPolicy "Delete" I0927 06:33:04.340] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:154 I0927 06:33:04.341] STEP: setting up the StorageClass I0927 06:33:04.341] STEP: creating a StorageClass I0927 06:33:04.418] STEP: setting up the PVC and PV I0927 06:33:04.418] STEP: creating a PVC I0927 06:33:04.499] STEP: waiting for PVC to be in phase "Bound" I0927 06:33:04.499] Sep 27 06:33:04.499: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-q7s8b] to have phase Bound I0927 06:33:04.576] Sep 27 06:33:04.576: INFO: PersistentVolumeClaim pvc-q7s8b found but phase is Pending instead of Bound. I0927 06:33:06.655] Sep 27 06:33:06.655: INFO: PersistentVolumeClaim pvc-q7s8b found and phase=Bound (2.156094748s) I0927 06:33:06.655] STEP: checking the PVC I0927 06:33:06.733] STEP: validating provisioned PV I0927 06:33:06.811] STEP: checking the PV I0927 06:33:06.811] Sep 27 06:33:06.810: INFO: deleting PVC "azurefile-6776"/"pvc-q7s8b" I0927 06:33:06.811] Sep 27 06:33:06.810: INFO: Deleting PersistentVolumeClaim "pvc-q7s8b" I0927 06:33:06.890] STEP: waiting for claim's PV "pvc-4b3f1e8d-e3e0-4744-9738-823446e498b9" to be deleted I0927 06:33:06.891] Sep 27 06:33:06.890: INFO: Waiting up to 10m0s for PersistentVolume pvc-4b3f1e8d-e3e0-4744-9738-823446e498b9 to get deleted I0927 06:33:06.968] Sep 27 06:33:06.968: INFO: PersistentVolume pvc-4b3f1e8d-e3e0-4744-9738-823446e498b9 found and phase=Released (77.678147ms) I0927 06:33:12.046] Sep 27 06:33:12.046: INFO: PersistentVolume pvc-4b3f1e8d-e3e0-4744-9738-823446e498b9 was removed I0927 06:33:12.047] Sep 27 06:33:12.046: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-6776 to be removed I0927 06:33:12.126] Sep 27 06:33:12.126: INFO: Claim "azurefile-6776" in namespace "pvc-q7s8b" doesn't exist in the system I0927 06:33:12.127] [AfterEach] Dynamic Provisioning I0927 06:33:12.127] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:33:12.127] Sep 27 06:33:12.126: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:33:12.279] STEP: Destroying namespace "azurefile-6776" for this suite. I0927 06:33:18.515] Sep 27 06:33:18.514: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:33:21.468] Sep 27 06:33:21.468: INFO: namespace azurefile-6776 deletion completed in 9.188848017s I0927 06:33:21.469] I0927 06:33:21.469] • [SLOW TEST:17.697 seconds] I0927 06:33:21.469] Dynamic Provisioning I0927 06:33:21.469] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I0927 06:33:21.469] should delete PV with reclaimPolicy "Delete" I0927 06:33:21.469] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:154 I0927 06:33:21.470] ------------------------------ I0927 06:33:21.470] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:21.470] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I0927 06:33:21.470] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:100 I0927 06:33:21.470] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:21.470] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:33:21.471] STEP: Creating a kubernetes client I0927 06:33:21.471] Sep 27 06:33:21.468: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:33:21.471] STEP: Building a namespace api object, basename azurefile I0927 06:33:21.703] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-715 I0927 06:33:21.962] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:33:22.039] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:22.039] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:48 I0927 06:33:22.040] [It] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I0927 06:33:22.040] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:100 I0927 06:33:44.858] STEP: Successfully provisioned AzureFile volume: "#fb391c02ce0f011e9ae7d02#pre-provisioned-retain-reclaimpolicy" I0927 06:33:44.868] I0927 06:33:44.868] STEP: setting up the PV I0927 06:33:44.868] STEP: creating a PV I0927 06:33:44.939] STEP: setting up the PVC I0927 06:33:44.939] STEP: creating a PVC I0927 06:33:45.034] STEP: waiting for PVC to be in phase "Bound" I0927 06:33:45.034] Sep 27 06:33:45.034: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-qr8wn] to have phase Bound I0927 06:33:45.112] Sep 27 06:33:45.112: INFO: PersistentVolumeClaim pvc-qr8wn found and phase=Bound (77.901641ms) I0927 06:33:45.112] STEP: checking the PVC I0927 06:33:45.190] STEP: validating provisioned PV I0927 06:33:45.267] STEP: checking the PV I0927 06:33:45.268] Sep 27 06:33:45.267: INFO: deleting PVC "azurefile-715"/"pvc-qr8wn" I0927 06:33:45.268] Sep 27 06:33:45.267: INFO: Deleting PersistentVolumeClaim "pvc-qr8wn" I0927 06:33:45.346] Sep 27 06:33:45.346: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-715 to be removed I0927 06:33:45.424] Sep 27 06:33:45.424: INFO: Claim "azurefile-715" in namespace "pvc-qr8wn" doesn't exist in the system I0927 06:33:45.424] Sep 27 06:33:45.424: INFO: Waiting up to 10m0s for PersistentVolume azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd to have phase Released I0927 06:33:45.502] Sep 27 06:33:45.502: INFO: PersistentVolume azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd found and phase=Released (77.760739ms) I0927 06:33:45.502] STEP: deleting PV "azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd" I0927 06:33:45.502] Sep 27 06:33:45.502: INFO: Deleting PersistentVolume "azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd" I0927 06:33:45.581] STEP: waiting for claim's PV "azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd" to be deleted I0927 06:33:45.581] Sep 27 06:33:45.581: INFO: Waiting up to 10m0s for PersistentVolume azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd to get deleted I0927 06:33:45.659] Sep 27 06:33:45.659: INFO: PersistentVolume azurefile-715-file.csi.azure.com-preprovsioned-pv-fhmqd was removed I0927 06:33:45.659] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:45.659] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:33:45.659] Sep 27 06:33:45.659: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:33:45.737] STEP: Destroying namespace "azurefile-715" for this suite. I0927 06:33:51.972] Sep 27 06:33:51.971: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:33:54.917] Sep 27 06:33:54.917: INFO: namespace azurefile-715 deletion completed in 9.179370351s I0927 06:33:54.917] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:54.917] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:54 I0927 06:33:55.338] I0927 06:33:55.339] • [SLOW TEST:33.870 seconds] I0927 06:33:55.339] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:55.339] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:36 I0927 06:33:55.340] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I0927 06:33:55.340] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:100 I0927 06:33:55.340] ------------------------------ I0927 06:33:55.340] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:55.341] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I0927 06:33:55.341] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:66 I0927 06:33:55.341] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:55.341] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:33:55.342] STEP: Creating a kubernetes client I0927 06:33:55.342] Sep 27 06:33:55.338: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:33:55.342] STEP: Building a namespace api object, basename azurefile I0927 06:33:55.577] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-5268 I0927 06:33:55.833] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:33:55.910] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:33:55.910] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:48 I0927 06:33:55.911] [It] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I0927 06:33:55.911] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:66 I0927 06:33:57.098] STEP: Successfully provisioned AzureFile volume: "#f7de16c83e0f011e9a9ed46#pre-provisioned-readonly" I0927 06:33:57.099] I0927 06:33:57.099] STEP: setting up the PV I0927 06:33:57.099] STEP: creating a PV I0927 06:33:57.177] STEP: setting up the PVC I0927 06:33:57.178] STEP: creating a PVC I0927 06:33:57.259] STEP: waiting for PVC to be in phase "Bound" I0927 06:33:57.259] Sep 27 06:33:57.259: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-2x595] to have phase Bound I0927 06:33:57.343] Sep 27 06:33:57.342: INFO: PersistentVolumeClaim pvc-2x595 found and phase=Bound (83.601692ms) I0927 06:33:57.343] STEP: checking the PVC I0927 06:33:57.421] STEP: validating provisioned PV I0927 06:33:57.498] STEP: checking the PV I0927 06:33:57.498] STEP: deploying the pod I0927 06:33:57.578] STEP: checking that the pods command exits with an error I0927 06:33:57.578] Sep 27 06:33:57.577: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vz496" in namespace "azurefile-5268" to be "Error status code" I0927 06:33:57.656] Sep 27 06:33:57.656: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 78.528744ms I0927 06:33:59.739] Sep 27 06:33:59.738: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 2.160971167s I0927 06:34:01.817] Sep 27 06:34:01.817: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 4.239425042s I0927 06:34:03.896] Sep 27 06:34:03.896: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 6.318887014s I0927 06:34:05.975] Sep 27 06:34:05.974: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 8.397123362s I0927 06:34:08.053] Sep 27 06:34:08.053: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 10.475718903s I0927 06:34:10.132] Sep 27 06:34:10.131: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 12.55413863s I0927 06:34:12.210] Sep 27 06:34:12.210: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 14.632510146s I0927 06:34:14.289] Sep 27 06:34:14.288: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 16.711004251s I0927 06:34:16.367] Sep 27 06:34:16.367: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 18.789368944s I0927 06:34:18.445] Sep 27 06:34:18.445: INFO: Pod "azurefile-volume-tester-vz496": Phase="Pending", Reason="", readiness=false. Elapsed: 20.867273721s I0927 06:34:20.524] Sep 27 06:34:20.523: INFO: Pod "azurefile-volume-tester-vz496": Phase="Failed", Reason="", readiness=false. Elapsed: 22.945918094s I0927 06:34:20.524] STEP: Saw pod failure I0927 06:34:20.524] Sep 27 06:34:20.523: INFO: Pod "azurefile-volume-tester-vz496" satisfied condition "Error status code" I0927 06:34:20.524] STEP: checking that pod logs contain expected message I0927 06:34:20.606] Sep 27 06:34:20.606: INFO: deleting Pod "azurefile-5268"/"azurefile-volume-tester-vz496" I0927 06:34:20.688] Sep 27 06:34:20.688: INFO: Pod azurefile-volume-tester-vz496 has the following logs: /bin/sh: can't create /mnt/test-1/data: Read-only file system I0927 06:34:20.688] I0927 06:34:20.688] STEP: Deleting pod azurefile-volume-tester-vz496 in namespace azurefile-5268 I0927 06:34:20.774] Sep 27 06:34:20.773: INFO: deleting PVC "azurefile-5268"/"pvc-2x595" I0927 06:34:20.774] Sep 27 06:34:20.773: INFO: Deleting PersistentVolumeClaim "pvc-2x595" I0927 06:34:20.854] Sep 27 06:34:20.853: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-5268 to be removed I0927 06:34:20.931] Sep 27 06:34:20.931: INFO: Claim "azurefile-5268" in namespace "pvc-2x595" doesn't exist in the system I0927 06:34:20.931] STEP: deleting PV "azurefile-5268-file.csi.azure.com-preprovsioned-pv-wfrb4" I0927 06:34:20.932] Sep 27 06:34:20.931: INFO: Deleting PersistentVolume "azurefile-5268-file.csi.azure.com-preprovsioned-pv-wfrb4" I0927 06:34:21.012] STEP: waiting for claim's PV "azurefile-5268-file.csi.azure.com-preprovsioned-pv-wfrb4" to be deleted I0927 06:34:21.012] Sep 27 06:34:21.012: INFO: Waiting up to 10m0s for PersistentVolume azurefile-5268-file.csi.azure.com-preprovsioned-pv-wfrb4 to get deleted I0927 06:34:21.089] Sep 27 06:34:21.089: INFO: PersistentVolume azurefile-5268-file.csi.azure.com-preprovsioned-pv-wfrb4 was removed I0927 06:34:21.090] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:34:21.090] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:34:21.090] Sep 27 06:34:21.089: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:34:21.243] STEP: Destroying namespace "azurefile-5268" for this suite. I0927 06:34:27.478] Sep 27 06:34:27.478: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:34:30.436] Sep 27 06:34:30.436: INFO: namespace azurefile-5268 deletion completed in 9.193749119s I0927 06:34:30.437] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:34:30.437] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:54 I0927 06:34:31.012] I0927 06:34:31.012] • [SLOW TEST:35.673 seconds] I0927 06:34:31.012] [azurefile-csi-e2e] [single-az] Pre-Provisioned I0927 06:34:31.012] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:36 I0927 06:34:31.013] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I0927 06:34:31.013] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/pre_provisioning.go:66 I0927 06:34:31.013] ------------------------------ I0927 06:34:31.013] Dynamic Provisioning I0927 06:34:31.014] should create a volume on demand I0927 06:34:31.014] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:45 I0927 06:34:31.014] [BeforeEach] Dynamic Provisioning I0927 06:34:31.015] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:34:31.015] STEP: Creating a kubernetes client I0927 06:34:31.015] Sep 27 06:34:31.011: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:34:31.018] STEP: Building a namespace api object, basename azurefile I0927 06:34:31.254] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-2868 I0927 06:34:31.509] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:34:31.586] [BeforeEach] Dynamic Provisioning I0927 06:34:31.586] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I0927 06:34:31.586] [It] should create a volume on demand I0927 06:34:31.587] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:45 I0927 06:34:31.587] STEP: setting up the StorageClass I0927 06:34:31.587] STEP: creating a StorageClass I0927 06:34:31.665] STEP: setting up the PVC and PV I0927 06:34:31.666] STEP: creating a PVC I0927 06:34:31.745] STEP: waiting for PVC to be in phase "Bound" I0927 06:34:31.745] Sep 27 06:34:31.745: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-86hrt] to have phase Bound I0927 06:34:31.822] Sep 27 06:34:31.822: INFO: PersistentVolumeClaim pvc-86hrt found but phase is Pending instead of Bound. I0927 06:34:33.900] Sep 27 06:34:33.900: INFO: PersistentVolumeClaim pvc-86hrt found and phase=Bound (2.155534423s) I0927 06:34:33.901] STEP: checking the PVC I0927 06:34:33.978] STEP: validating provisioned PV I0927 06:34:34.056] STEP: checking the PV I0927 06:34:34.056] STEP: deploying the pod I0927 06:34:34.135] STEP: checking that the pods command exits with no error I0927 06:34:34.135] Sep 27 06:34:34.135: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-d8ng5" in namespace "azurefile-2868" to be "success or failure" I0927 06:34:34.214] Sep 27 06:34:34.214: INFO: Pod "azurefile-volume-tester-d8ng5": Phase="Pending", Reason="", readiness=false. Elapsed: 79.065841ms I0927 06:34:36.292] Sep 27 06:34:36.292: INFO: Pod "azurefile-volume-tester-d8ng5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.157122324s I0927 06:34:38.371] Sep 27 06:34:38.370: INFO: Pod "azurefile-volume-tester-d8ng5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.235325398s I0927 06:34:40.449] Sep 27 06:34:40.448: INFO: Pod "azurefile-volume-tester-d8ng5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.313407159s I0927 06:34:42.527] Sep 27 06:34:42.527: INFO: Pod "azurefile-volume-tester-d8ng5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.391703812s I0927 06:34:44.605] Sep 27 06:34:44.605: INFO: Pod "azurefile-volume-tester-d8ng5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.470067955s I0927 06:34:44.606] STEP: Saw pod success I0927 06:34:44.606] Sep 27 06:34:44.605: INFO: Pod "azurefile-volume-tester-d8ng5" satisfied condition "success or failure" I0927 06:34:44.606] Sep 27 06:34:44.605: INFO: deleting Pod "azurefile-2868"/"azurefile-volume-tester-d8ng5" I0927 06:34:44.687] Sep 27 06:34:44.687: INFO: Pod azurefile-volume-tester-d8ng5 has the following logs: hello world I0927 06:34:44.687] I0927 06:34:44.688] STEP: Deleting pod azurefile-volume-tester-d8ng5 in namespace azurefile-2868 I0927 06:34:44.779] Sep 27 06:34:44.778: INFO: deleting PVC "azurefile-2868"/"pvc-86hrt" I0927 06:34:44.779] Sep 27 06:34:44.778: INFO: Deleting PersistentVolumeClaim "pvc-86hrt" I0927 06:34:44.859] STEP: waiting for claim's PV "pvc-f243bc4f-b723-401f-9c6a-1a110e3900c6" to be deleted I0927 06:34:44.859] Sep 27 06:34:44.858: INFO: Waiting up to 10m0s for PersistentVolume pvc-f243bc4f-b723-401f-9c6a-1a110e3900c6 to get deleted I0927 06:34:44.936] Sep 27 06:34:44.936: INFO: PersistentVolume pvc-f243bc4f-b723-401f-9c6a-1a110e3900c6 found and phase=Released (77.776028ms) I0927 06:34:50.014] Sep 27 06:34:50.014: INFO: PersistentVolume pvc-f243bc4f-b723-401f-9c6a-1a110e3900c6 was removed I0927 06:34:50.015] Sep 27 06:34:50.014: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2868 to be removed I0927 06:34:50.092] Sep 27 06:34:50.092: INFO: Claim "azurefile-2868" in namespace "pvc-86hrt" doesn't exist in the system I0927 06:34:50.092] Sep 27 06:34:50.092: INFO: deleting StorageClass azurefile-2868-file.csi.azure.com-dynamic-sc-d7pqr I0927 06:34:50.172] [AfterEach] Dynamic Provisioning I0927 06:34:50.173] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:34:50.173] Sep 27 06:34:50.172: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:34:50.326] STEP: Destroying namespace "azurefile-2868" for this suite. I0927 06:34:56.561] Sep 27 06:34:56.561: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:34:59.473] Sep 27 06:34:59.472: INFO: namespace azurefile-2868 deletion completed in 9.147118615s I0927 06:34:59.473] I0927 06:34:59.473] • [SLOW TEST:28.461 seconds] I0927 06:34:59.474] Dynamic Provisioning I0927 06:34:59.474] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I0927 06:34:59.474] should create a volume on demand I0927 06:34:59.474] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:45 I0927 06:34:59.475] ------------------------------ I0927 06:34:59.475] Dynamic Provisioning I0927 06:34:59.475] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I0927 06:34:59.475] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:67 I0927 06:34:59.475] [BeforeEach] Dynamic Provisioning I0927 06:34:59.476] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I0927 06:34:59.476] STEP: Creating a kubernetes client I0927 06:34:59.476] Sep 27 06:34:59.473: INFO: >>> kubeConfig: /workspace/aks455019149/kubeconfig/kubeconfig.eastus2.json I0927 06:34:59.476] STEP: Building a namespace api object, basename azurefile I0927 06:34:59.708] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-2109 I0927 06:34:59.964] STEP: Waiting for a default service account to be provisioned in namespace I0927 06:35:00.041] [BeforeEach] Dynamic Provisioning I0927 06:35:00.041] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I0927 06:35:00.041] [It] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I0927 06:35:00.042] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:67 I0927 06:35:00.042] STEP: setting up the StorageClass I0927 06:35:00.042] STEP: creating a StorageClass I0927 06:35:00.122] STEP: setting up the PVC and PV I0927 06:35:00.123] STEP: creating a PVC I0927 06:35:00.212] STEP: waiting for PVC to be in phase "Bound" I0927 06:35:00.212] Sep 27 06:35:00.212: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-8n2sh] to have phase Bound I0927 06:35:00.290] Sep 27 06:35:00.290: INFO: PersistentVolumeClaim pvc-8n2sh found but phase is Pending instead of Bound. I0927 06:35:02.368] Sep 27 06:35:02.368: INFO: PersistentVolumeClaim pvc-8n2sh found and phase=Bound (2.15650478s) I0927 06:35:02.369] STEP: checking the PVC I0927 06:35:02.451] STEP: validating provisioned PV I0927 06:35:02.529] STEP: checking the PV I0927 06:35:02.529] STEP: deploying the pod I0927 06:35:02.608] STEP: checking that the pod is running I0927 06:35:16.764] STEP: setting up the StorageClass I0927 06:35:16.764] STEP: creating a StorageClass I0927 06:35:16.842] STEP: setting up the PVC and PV I0927 06:35:16.842] STEP: creating a PVC I0927 06:35:16.921] STEP: waiting for PVC to be in phase "Bound" I0927 06:35:16.922] Sep 27 06:35:16.921: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-pk8km] to have phase Bound I0927 06:35:16.999] Sep 27 06:35:16.999: INFO: PersistentVolumeClaim pvc-pk8km found but phase is Pending instead of Bound. I0927 06:35:19.078] Sep 27 06:35:19.077: INFO: PersistentVolumeClaim pvc-pk8km found and phase=Bound (2.156025491s) I0927 06:35:19.078] STEP: checking the PVC I0927 06:35:19.155] STEP: validating provisioned PV I0927 06:35:19.233] STEP: checking the PV I0927 06:35:19.233] STEP: deploying the pod I0927 06:35:19.312] STEP: checking that the pod is running I0927 06:35:33.468] Sep 27 06:35:33.468: INFO: deleting Pod "azurefile-2109"/"azurefile-volume-tester-cpsqt" I0927 06:35:33.553] Sep 27 06:35:33.553: INFO: Pod azurefile-volume-tester-cpsqt has the following logs: I0927 06:35:33.553] STEP: Deleting pod azurefile-volume-tester-cpsqt in namespace azurefile-2109 I0927 06:35:33.634] Sep 27 06:35:33.633: INFO: deleting PVC "azurefile-2109"/"pvc-pk8km" I0927 06:35:33.634] Sep 27 06:35:33.634: INFO: Deleting PersistentVolumeClaim "pvc-pk8km" I0927 06:35:33.717] STEP: waiting for claim's PV "pvc-31b5e9cc-0835-429c-af14-34497293924c" to be deleted I0927 06:35:33.718] Sep 27 06:35:33.717: INFO: Waiting up to 10m0s for PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c to get deleted I0927 06:35:33.795] Sep 27 06:35:33.795: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (77.89422ms) I0927 06:35:38.874] Sep 27 06:35:38.873: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (5.156144993s) I0927 06:35:43.952] Sep 27 06:35:43.951: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (10.234381509s) I0927 06:35:49.030] Sep 27 06:35:49.030: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (15.312399866s) I0927 06:35:54.108] Sep 27 06:35:54.108: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (20.390983571s) I0927 06:35:59.189] Sep 27 06:35:59.188: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (25.471303837s) I0927 06:36:04.267] Sep 27 06:36:04.267: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c found and phase=Bound (30.549932232s) I0927 06:36:09.345] Sep 27 06:36:09.345: INFO: PersistentVolume pvc-31b5e9cc-0835-429c-af14-34497293924c was removed I0927 06:36:09.346] Sep 27 06:36:09.345: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2109 to be removed I0927 06:36:09.423] Sep 27 06:36:09.423: INFO: Claim "azurefile-2109" in namespace "pvc-pk8km" doesn't exist in the system I0927 06:36:09.423] Sep 27 06:36:09.423: INFO: deleting StorageClass azurefile-2109-file.csi.azure.com-dynamic-sc-dr5k9 I0927 06:36:09.503] Sep 27 06:36:09.503: INFO: deleting Pod "azurefile-2109"/"azurefile-volume-tester-pkcxq" I0927 06:36:09.586] Sep 27 06:36:09.586: INFO: Pod azurefile-volume-tester-pkcxq has the following logs: I0927 06:36:09.586] STEP: Deleting pod azurefile-volume-tester-pkcxq in namespace azurefile-2109 I0927 06:36:09.666] Sep 27 06:36:09.666: INFO: deleting PVC "azurefile-2109"/"pvc-8n2sh" I0927 06:36:09.667] Sep 27 06:36:09.666: INFO: Deleting PersistentVolumeClaim "pvc-8n2sh" I0927 06:36:09.755] STEP: waiting for claim's PV "pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06" to be deleted I0927 06:36:09.756] Sep 27 06:36:09.755: INFO: Waiting up to 10m0s for PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 to get deleted I0927 06:36:09.833] Sep 27 06:36:09.833: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (78.053115ms) I0927 06:36:14.912] Sep 27 06:36:14.911: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (5.156391293s) I0927 06:36:19.990] Sep 27 06:36:19.990: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (10.235121521s) I0927 06:36:25.072] Sep 27 06:36:25.072: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (15.316661322s) I0927 06:36:30.151] Sep 27 06:36:30.151: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (20.395564246s) I0927 06:36:35.229] Sep 27 06:36:35.229: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (25.473813512s) I0927 06:36:40.308] Sep 27 06:36:40.308: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (30.552577831s) I0927 06:36:45.386] Sep 27 06:36:45.386: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 found and phase=Bound (35.630835694s) I0927 06:36:50.465] Sep 27 06:36:50.465: INFO: PersistentVolume pvc-ce0bab2e-de7a-4c58-9561-d42ca4e86e06 was removed I0927 06:36:50.465] Sep 27 06:36:50.465: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2109 to be removed I0927 06:36:50.543] Sep 27 06:36:50.543: INFO: Claim "azurefile-2109" in namespace "pvc-8n2sh" doesn't exist in the system I0927 06:36:50.543] Sep 27 06:36:50.543: INFO: deleting StorageClass azurefile-2109-file.csi.azure.com-dynamic-sc-6qf4d I0927 06:36:50.623] [AfterEach] Dynamic Provisioning I0927 06:36:50.623] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I0927 06:36:50.624] Sep 27 06:36:50.623: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I0927 06:36:50.776] STEP: Destroying namespace "azurefile-2109" for this suite. I0927 06:36:57.013] Sep 27 06:36:57.012: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I0927 06:36:59.982] Sep 27 06:36:59.982: INFO: namespace azurefile-2109 deletion completed in 9.205906761s I0927 06:36:59.982] I0927 06:36:59.982] • [SLOW TEST:120.509 seconds] I0927 06:36:59.983] Dynamic Provisioning I0927 06:36:59.983] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I0927 06:36:59.983] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I0927 06:36:59.983] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:67 I0927 06:36:59.983] ------------------------------ I0927 06:36:59.984] 2019/09/27 06:36:59 Uninstalling Azure File CSI Driver... I0927 06:36:59.985] make[1]: Entering directory '/go/src/github.com/kubernetes-sigs/azurefile-csi-driver' I0927 06:36:59.985] helm delete --purge azurefile-csi-driver I0927 06:37:07.691] release "azurefile-csi-driver" deleted I0927 06:37:07.693] make[1]: Leaving directory '/go/src/github.com/kubernetes-sigs/azurefile-csi-driver' I0927 06:37:07.693] 2019/09/27 06:37:07 Azure File CSI Driver uninstalled I0927 06:37:07.693] I0927 06:37:07.694] I0927 06:37:07.694] Summarizing 1 Failure: I0927 06:37:07.694] I0927 06:37:07.694] [Fail] Dynamic Provisioning [It] should create a deployment object, write and read to it, delete the pod and write and read to it again I0927 06:37:07.694] /go/src/github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:272 I0927 06:37:07.694] I0927 06:37:07.694] Ran 8 of 8 Specs in 821.401 seconds I0927 06:37:07.695] FAIL! -- 7 Passed | 1 Failed | 0 Pending | 0 Skipped I0927 06:37:07.695] --- FAIL: TestE2E (821.40s) I0927 06:37:07.695] FAIL I0927 06:37:07.697] FAIL github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e 821.454s I0927 06:37:07.991] Makefile:58: recipe for target 'e2e-test' failed W0927 06:37:08.091] make: *** [e2e-test] Error 1 W0927 06:37:08.091] 2019/09/27 06:37:07 process.go:155: Step 'make e2e-test' finished in 15m18.056810257s W0927 06:37:08.091] 2019/09/27 06:37:07 azure.go:899: Deleting resource group: kubetest-c777fbc9-e0ea-11e9-b6da-0242c9e6f69d. W0927 06:47:17.722] 2019/09/27 06:47:17 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W0927 06:47:17.723] 2019/09/27 06:47:17 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W0927 06:47:18.411] 2019/09/27 06:47:18 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 688.378765ms W0927 06:47:18.411] 2019/09/27 06:47:18 main.go:319: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] W0927 06:47:18.415] Traceback (most recent call last): W0927 06:47:18.415] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in W0927 06:47:18.416] main(parse_args()) W0927 06:47:18.416] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W0927 06:47:18.416] mode.start(runner_args) W0927 06:47:18.416] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W0927 06:47:18.416] check_env(env, self.command, *args) W0927 06:47:18.416] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W0927 06:47:18.417] subprocess.check_call(cmd, env=env) W0927 06:47:18.417] File "/usr/lib/python2.7/subprocess.py", line 186, in check_call W0927 06:47:18.417] raise CalledProcessError(retcode, cmd) W0927 06:47:18.419] 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=1', '--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-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', '--test-azure-file-csi-driver=True')' returned non-zero exit status 1 E0927 06:47:18.426] Command failed I0927 06:47:18.426] process 689 exited with code 1 after 56.3m E0927 06:47:18.426] FAIL: pull-azurefile-csi-driver-e2e I0927 06:47:18.426] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W0927 06:47:19.189] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I0927 06:47:19.220] process 23425 exited with code 0 after 0.0m I0927 06:47:19.220] Call: gcloud config get-value account I0927 06:47:19.457] process 23437 exited with code 0 after 0.0m I0927 06:47:19.458] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I0927 06:47:19.458] Upload result and artifacts... I0927 06:47:19.458] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424 I0927 06:47:19.458] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424/artifacts W0927 06:47:20.612] CommandException: One or more URLs matched no objects. E0927 06:47:20.696] Command failed I0927 06:47:20.697] process 23449 exited with code 1 after 0.0m W0927 06:47:20.697] Remote dir gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424/artifacts not exist yet I0927 06:47:20.697] Call: gsutil -m -q -o GSUtil:use_magicfile=True cp -r -c -z log,txt,xml /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424/artifacts I0927 06:47:22.351] process 23591 exited with code 0 after 0.0m I0927 06:47:22.352] Call: git rev-parse HEAD I0927 06:47:22.354] process 24118 exited with code 0 after 0.0m I0927 06:47:22.355] Call: git rev-parse HEAD I0927 06:47:22.358] process 24119 exited with code 0 after 0.0m I0927 06:47:22.358] Call: gsutil stat gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/jobResultsCache.json I0927 06:47:23.324] process 24120 exited with code 0 after 0.0m I0927 06:47:23.325] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/jobResultsCache.json#1569562432413591' I0927 06:47:24.665] process 24262 exited with code 0 after 0.0m I0927 06:47:24.666] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1569562432413591 cp /tmp/gsutil_LOHvRP gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/jobResultsCache.json I0927 06:47:25.940] process 24406 exited with code 0 after 0.0m I0927 06:47:25.941] Call: gsutil stat gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/jobResultsCache.json I0927 06:47:26.959] process 24584 exited with code 0 after 0.0m I0927 06:47:26.959] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/jobResultsCache.json#1569562435790164' I0927 06:47:28.102] process 24726 exited with code 0 after 0.0m I0927 06:47:28.103] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1569562435790164 cp /tmp/gsutil_u3MC14 gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/jobResultsCache.json I0927 06:47:29.412] process 24870 exited with code 0 after 0.0m I0927 06:47:29.413] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_uN8YrM gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1177460284827111424/finished.json I0927 06:47:30.741] process 25048 exited with code 0 after 0.0m I0927 06:47:30.741] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_ABAbQ4 gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/latest-build.txt I0927 06:47:32.014] process 25226 exited with code 0 after 0.0m I0927 06:47:32.015] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_TdIqO1 gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/latest-build.txt I0927 06:47:33.418] process 25404 exited with code 0 after 0.0m