W1003 22:09:09.380] ************************************************************************** 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 ************************************************************************** I1003 22:09:09.381] Args: --job=pull-azuredisk-csi-driver-e2e --service-account=/etc/service-account/service-account.json --upload=gs://kubernetes-jenkins/logs --job=pull-azuredisk-csi-driver-e2e --root=/go/src --service-account=/etc/service-account/service-account.json --repo=k8s.io/kubernetes --repo=github.com/kubernetes-sigs/azuredisk-csi-driver=master:6b4d4209385f8a3b04a39f1970017a27f2667a9a,166:e7264e0f9abbf0764bb810470367384df2eed149 --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-disk-csi-driver=True I1003 22:09:09.381] Bootstrap pull-azuredisk-csi-driver-e2e... I1003 22:09:09.387] Builder: 4dbee499-e62a-11e9-918b-16773c0c7aed I1003 22:09:09.388] Image: chewong/kubekins-e2e:v20191002-b557491-azuredisk-csi-driver-job I1003 22:09:09.388] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779 I1003 22:09:09.388] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1003 22:09:10.566] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1003 22:09:10.612] process 214 exited with code 0 after 0.0m I1003 22:09:10.612] Call: gcloud config get-value account I1003 22:09:10.973] process 226 exited with code 0 after 0.0m I1003 22:09:10.973] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1003 22:09:10.973] Root: /go/src I1003 22:09:10.974] cd to /go/src I1003 22:09:10.974] Checkout: /go/src/k8s.io/kubernetes master to /go/src/k8s.io/kubernetes I1003 22:09:10.974] Call: git init k8s.io/kubernetes I1003 22:09:10.982] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/ I1003 22:09:10.986] process 238 exited with code 0 after 0.0m I1003 22:09:10.986] Call: git config --local user.name 'K8S Bootstrap' I1003 22:09:10.992] process 239 exited with code 0 after 0.0m I1003 22:09:10.992] Call: git config --local user.email k8s_bootstrap@localhost I1003 22:09:10.996] process 240 exited with code 0 after 0.0m I1003 22:09:10.996] Call: git fetch --quiet --tags https://github.com/kubernetes/kubernetes master I1003 22:11:17.163] process 241 exited with code 0 after 2.1m I1003 22:11:17.164] Call: git checkout -B test FETCH_HEAD W1003 22:11:21.333] Switched to a new branch 'test' I1003 22:11:21.347] process 255 exited with code 0 after 0.1m I1003 22:11:21.347] Call: git show -s --format=format:%ct HEAD I1003 22:11:21.366] process 256 exited with code 0 after 0.0m I1003 22:11:21.367] Checkout: /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver master:6b4d4209385f8a3b04a39f1970017a27f2667a9a,166:e7264e0f9abbf0764bb810470367384df2eed149 to /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver I1003 22:11:21.367] Call: git init github.com/kubernetes-sigs/azuredisk-csi-driver I1003 22:11:21.374] Initialized empty Git repository in /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/.git/ I1003 22:11:21.375] process 257 exited with code 0 after 0.0m I1003 22:11:21.378] Call: git config --local user.name 'K8S Bootstrap' I1003 22:11:21.386] process 258 exited with code 0 after 0.0m I1003 22:11:21.386] Call: git config --local user.email k8s_bootstrap@localhost I1003 22:11:21.394] process 259 exited with code 0 after 0.0m I1003 22:11:21.395] Call: git fetch --quiet --tags https://github.com/kubernetes-sigs/azuredisk-csi-driver master +refs/pull/166/head:refs/pr/166 I1003 22:11:34.919] process 260 exited with code 0 after 0.2m I1003 22:11:34.920] Call: git checkout -B test 6b4d4209385f8a3b04a39f1970017a27f2667a9a W1003 22:11:35.910] Switched to a new branch 'test' I1003 22:11:35.911] process 272 exited with code 0 after 0.0m I1003 22:11:35.911] Call: git show -s --format=format:%ct HEAD I1003 22:11:35.922] process 273 exited with code 0 after 0.0m I1003 22:11:35.922] Call: git merge --no-ff -m 'Merge +refs/pull/166/head:refs/pr/166' e7264e0f9abbf0764bb810470367384df2eed149 I1003 22:11:36.674] Removing test/integration/azure.json I1003 22:11:36.678] Removing test/e2e/run-test.sh I1003 22:11:36.678] Removing .travis.yml I1003 22:11:36.679] Merge made by the 'recursive' strategy. I1003 22:11:36.697] .travis.yml | 36 - I1003 22:11:36.697] Gopkg.lock | 18 +- I1003 22:11:36.698] Makefile | 103 +- I1003 22:11:36.699] .../templates/csi-azuredisk-controller.yaml | 1 + I1003 22:11:36.699] .../templates/csi-azuredisk-node.yaml | 1 - I1003 22:11:36.700] deploy/csi-azuredisk-controller.yaml | 1 + I1003 22:11:36.700] deploy/csi-azuredisk-node.yaml | 1 - I1003 22:11:36.701] hack/verify-all.sh | 2 +- I1003 22:11:36.701] hack/verify-dep.sh | 1 + I1003 22:11:36.702] hack/verify-gofmt.sh | 2 +- I1003 22:11:36.702] hack/verify-golint.sh | 7 +- I1003 22:11:36.703] pkg/azuredisk/controllerserver.go | 2 +- I1003 22:11:36.703] pkg/azuredisk/nodeserver.go | 10 +- I1003 22:11:36.704] test/e2e/dynamic_provisioning.go | 10 - I1003 22:11:36.704] test/e2e/pre_provisioning.go | 16 +- I1003 22:11:36.705] test/e2e/run-test.sh | 37 - I1003 22:11:36.705] test/e2e/suite_test.go | 87 + I1003 22:11:36.706] test/integration/azure.json | 33 - I1003 22:11:36.706] test/integration/integration_test.go | 100 + I1003 22:11:36.707] test/integration/run-test.sh | 157 +- I1003 22:11:36.707] test/integration/run-tests-all-clouds.sh | 32 +- I1003 22:11:36.714] test/sanity/run-test.sh | 47 +- I1003 22:11:36.714] test/sanity/run-tests-all-clouds.sh | 35 +- I1003 22:11:36.714] test/sanity/sanity_test.go | 76 +- I1003 22:11:36.715] test/utils/azure/azure_helpers.go | 246 +++ I1003 22:11:36.715] test/utils/credentials/credentials.go | 188 ++ I1003 22:11:36.715] test/utils/credentials/credentials_test.go | 181 ++ I1003 22:11:36.715] test/utils/testutil/testutil.go | 8 + I1003 22:11:36.715] .../resources/mgmt/2018-05-01/resources/client.go | 51 + I1003 22:11:36.716] .../2018-05-01/resources/deploymentoperations.go | 474 +++++ I1003 22:11:36.716] .../mgmt/2018-05-01/resources/deployments.go | 1553 +++++++++++++++ I1003 22:11:36.716] .../resources/mgmt/2018-05-01/resources/groups.go | 676 +++++++ I1003 22:11:36.716] .../resources/mgmt/2018-05-01/resources/models.go | 2044 ++++++++++++++++++++ I1003 22:11:36.716] .../mgmt/2018-05-01/resources/operations.go | 147 ++ I1003 22:11:36.717] .../mgmt/2018-05-01/resources/providers.go | 392 ++++ I1003 22:11:36.717] .../mgmt/2018-05-01/resources/resources.go | 1352 +++++++++++++ I1003 22:11:36.717] .../resources/mgmt/2018-05-01/resources/tags.go | 454 +++++ I1003 22:11:36.717] .../resources/mgmt/2018-05-01/resources/version.go | 30 + I1003 22:11:36.722] vendor/github.com/pelletier/go-toml/LICENSE | 21 + I1003 22:11:36.722] vendor/github.com/pelletier/go-toml/doc.go | 23 + I1003 22:11:36.722] vendor/github.com/pelletier/go-toml/fuzz.go | 31 + I1003 22:11:36.722] vendor/github.com/pelletier/go-toml/keysparsing.go | 113 ++ I1003 22:11:36.722] vendor/github.com/pelletier/go-toml/lexer.go | 752 +++++++ I1003 22:11:36.723] vendor/github.com/pelletier/go-toml/marshal.go | 803 ++++++++ I1003 22:11:36.723] vendor/github.com/pelletier/go-toml/parser.go | 442 +++++ I1003 22:11:36.723] vendor/github.com/pelletier/go-toml/position.go | 29 + I1003 22:11:36.723] vendor/github.com/pelletier/go-toml/token.go | 144 ++ I1003 22:11:36.724] vendor/github.com/pelletier/go-toml/toml.go | 393 ++++ I1003 22:11:36.724] .../pelletier/go-toml/tomltree_create.go | 142 ++ I1003 22:11:36.724] .../github.com/pelletier/go-toml/tomltree_write.go | 434 +++++ I1003 22:11:36.724] 50 files changed, 11564 insertions(+), 374 deletions(-) I1003 22:11:36.724] delete mode 100644 .travis.yml I1003 22:11:36.725] delete mode 100755 test/e2e/run-test.sh I1003 22:11:36.725] delete mode 100644 test/integration/azure.json I1003 22:11:36.725] create mode 100644 test/integration/integration_test.go I1003 22:11:36.725] create mode 100644 test/utils/azure/azure_helpers.go I1003 22:11:36.725] create mode 100644 test/utils/credentials/credentials.go I1003 22:11:36.730] create mode 100644 test/utils/credentials/credentials_test.go I1003 22:11:36.731] create mode 100644 test/utils/testutil/testutil.go I1003 22:11:36.731] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/client.go I1003 22:11:36.731] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/deploymentoperations.go I1003 22:11:36.731] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/deployments.go I1003 22:11:36.732] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/groups.go I1003 22:11:36.732] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/models.go I1003 22:11:36.732] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/operations.go I1003 22:11:36.732] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/providers.go I1003 22:11:36.733] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/resources.go I1003 22:11:36.733] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/tags.go I1003 22:11:36.733] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/version.go I1003 22:11:36.733] create mode 100644 vendor/github.com/pelletier/go-toml/LICENSE I1003 22:11:36.738] create mode 100644 vendor/github.com/pelletier/go-toml/doc.go I1003 22:11:36.738] create mode 100644 vendor/github.com/pelletier/go-toml/fuzz.go I1003 22:11:36.738] create mode 100644 vendor/github.com/pelletier/go-toml/keysparsing.go I1003 22:11:36.738] create mode 100644 vendor/github.com/pelletier/go-toml/lexer.go I1003 22:11:36.738] create mode 100644 vendor/github.com/pelletier/go-toml/marshal.go I1003 22:11:36.739] create mode 100644 vendor/github.com/pelletier/go-toml/parser.go I1003 22:11:36.739] create mode 100644 vendor/github.com/pelletier/go-toml/position.go I1003 22:11:36.739] create mode 100644 vendor/github.com/pelletier/go-toml/token.go I1003 22:11:36.739] create mode 100644 vendor/github.com/pelletier/go-toml/toml.go I1003 22:11:36.739] create mode 100644 vendor/github.com/pelletier/go-toml/tomltree_create.go I1003 22:11:36.740] create mode 100644 vendor/github.com/pelletier/go-toml/tomltree_write.go I1003 22:11:36.740] process 274 exited with code 0 after 0.0m I1003 22:11:36.740] Configure environment... I1003 22:11:36.741] Call: git show -s --format=format:%ct HEAD I1003 22:11:36.762] process 276 exited with code 0 after 0.0m I1003 22:11:36.762] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1003 22:11:38.662] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1003 22:11:38.882] process 277 exited with code 0 after 0.0m I1003 22:11:38.882] Call: gcloud config get-value account I1003 22:11:39.462] process 289 exited with code 0 after 0.0m I1003 22:11:39.462] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1003 22:11:39.462] 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 ' I1003 22:11:40.333] process 301 exited with code 0 after 0.0m I1003 22:11:40.336] Start 1179880985387339779 at v1.17.0-alpha.1.30+3317805652d145... I1003 22:11:40.340] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_mXHPDS gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779/started.json I1003 22:11:43.608] process 334 exited with code 0 after 0.1m I1003 22:11:43.609] Call: gsutil -q -h Content-Type:text/plain -h 'x-goog-meta-link: gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779' cp /tmp/gsutil_cpi3Vl gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-e2e/1179880985387339779.txt I1003 22:11:46.960] process 512 exited with code 0 after 0.1m I1003 22:11:46.961] 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-disk-csi-driver=True W1003 22:11:47.080] starts with local mode W1003 22:11:47.081] Environment: W1003 22:11:47.081] ARTIFACTS=/workspace/_artifacts W1003 22:11:47.082] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa W1003 22:11:47.082] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub W1003 22:11:47.082] AZURE_CREDENTIALS=/etc/azure-cred/credentials W1003 22:11:47.083] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub W1003 22:11:47.083] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer W1003 22:11:47.083] BAZEL_REMOTE_CACHE_ENABLED=false W1003 22:11:47.084] BAZEL_VERSION=0.23.2 W1003 22:11:47.084] BOOTSTRAP_MIGRATION=yes W1003 22:11:47.084] BUILD_ID=1179880985387339779 W1003 22:11:47.085] BUILD_NUMBER=1179880985387339779 W1003 22:11:47.085] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true W1003 22:11:47.087] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud W1003 22:11:47.087] CLOUDSDK_CORE_DISABLE_PROMPTS=1 W1003 22:11:47.088] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false W1003 22:11:47.088] CLOUD_CONFIG=random W1003 22:11:47.089] DECK_PORT=tcp://10.0.160.83:80 W1003 22:11:47.089] DECK_PORT_80_TCP=tcp://10.0.160.83:80 W1003 22:11:47.090] DECK_PORT_80_TCP_ADDR=10.0.160.83 W1003 22:11:47.090] DECK_PORT_80_TCP_PORT=80 W1003 22:11:47.091] DECK_PORT_80_TCP_PROTO=tcp W1003 22:11:47.091] DECK_SERVICE_HOST=10.0.160.83 W1003 22:11:47.091] DECK_SERVICE_PORT=80 W1003 22:11:47.092] DOCKER_IN_DOCKER_ENABLED=true W1003 22:11:47.092] DOCKER_IN_DOCKER_IPV6_ENABLED=false W1003 22:11:47.092] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779/artifacts W1003 22:11:47.093] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json W1003 22:11:47.093] GOPATH=/go W1003 22:11:47.093] GO_TARBALL=go1.12.1.linux-amd64.tar.gz W1003 22:11:47.094] HOME=/workspace W1003 22:11:47.094] HOOK_PORT=tcp://10.0.144.133:8888 W1003 22:11:47.094] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888 W1003 22:11:47.095] HOOK_PORT_8888_TCP_ADDR=10.0.144.133 W1003 22:11:47.095] HOOK_PORT_8888_TCP_PORT=8888 W1003 22:11:47.095] HOOK_PORT_8888_TCP_PROTO=tcp W1003 22:11:47.096] HOOK_SERVICE_HOST=10.0.144.133 W1003 22:11:47.096] HOOK_SERVICE_PORT=8888 W1003 22:11:47.096] HOSTNAME=4dbee499-e62a-11e9-918b-16773c0c7aed W1003 22:11:47.097] IMAGE=chewong/kubekins-e2e:v20191002-b557491-azuredisk-csi-driver-job W1003 22:11:47.097] INSTANCE_PREFIX=bootstrap-e2e W1003 22:11:47.098] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine W1003 22:11:47.098] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub W1003 22:11:47.098] JOB_NAME=pull-azuredisk-csi-driver-e2e W1003 22:11:47.099] JOB_SPEC={"type":"presubmit","job":"pull-azuredisk-csi-driver-e2e","buildid":"1179880985387339779","prowjobid":"4dbee499-e62a-11e9-918b-16773c0c7aed","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"3317805652d145c4003f5c534c7d87fb5cd87d50","base_link":"https://github.com/Azure/kubernetes/commit/3317805652d145c4003f5c534c7d87fb5cd87d50","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"}]}} W1003 22:11:47.099] JOB_TYPE=presubmit W1003 22:11:47.100] KUBERNETES_PORT=tcp://10.0.0.1:443 W1003 22:11:47.100] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443 W1003 22:11:47.100] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1 W1003 22:11:47.101] KUBERNETES_PORT_443_TCP_PORT=443 W1003 22:11:47.101] KUBERNETES_PORT_443_TCP_PROTO=tcp W1003 22:11:47.101] KUBERNETES_SERVICE_HOST=10.0.0.1 W1003 22:11:47.102] KUBERNETES_SERVICE_PORT=443 W1003 22:11:47.102] KUBERNETES_SERVICE_PORT_HTTPS=443 W1003 22:11:47.102] KUBETEST_IN_DOCKER=true W1003 22:11:47.103] KUBETEST_MANUAL_DUMP=y W1003 22:11:47.103] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e W1003 22:11:47.103] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e W1003 22:11:47.104] KUBE_VERBOSE=0 W1003 22:11:47.104] NODE_NAME=4dbee499-e62a-11e9-918b-16773c0c7aed W1003 22:11:47.105] 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 W1003 22:11:47.105] PROW_JOB_ID=4dbee499-e62a-11e9-918b-16773c0c7aed W1003 22:11:47.105] PULL_BASE_REF=master W1003 22:11:47.106] PULL_BASE_SHA=3317805652d145c4003f5c534c7d87fb5cd87d50 W1003 22:11:47.106] PULL_NUMBER=113 W1003 22:11:47.106] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822 W1003 22:11:47.107] PULL_REFS=master:3317805652d145c4003f5c534c7d87fb5cd87d50,113:879465972041635fd7bc8269da49153b67e63822 W1003 22:11:47.108] PWD=/workspace W1003 22:11:47.108] REGISTRY=k8sprowinternal.azurecr.io W1003 22:11:47.108] REPO_NAME=kubernetes W1003 22:11:47.109] REPO_OWNER=Azure W1003 22:11:47.110] SHLVL=2 W1003 22:11:47.110] SOURCE_DATE_EPOCH=1570138794 W1003 22:11:47.110] TERM=xterm W1003 22:11:47.111] TIDE_PORT=tcp://10.0.180.53:80 W1003 22:11:47.111] TIDE_PORT_80_TCP=tcp://10.0.180.53:80 W1003 22:11:47.111] TIDE_PORT_80_TCP_ADDR=10.0.180.53 W1003 22:11:47.112] TIDE_PORT_80_TCP_PORT=80 W1003 22:11:47.112] TIDE_PORT_80_TCP_PROTO=tcp W1003 22:11:47.112] TIDE_SERVICE_HOST=10.0.180.53 W1003 22:11:47.112] TIDE_SERVICE_PORT=80 W1003 22:11:47.113] WORKSPACE=/workspace W1003 22:11:47.113] _=./test-infra/jenkins/bootstrap.py W1003 22:11:47.114] 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-disk-csi-driver=True') W1003 22:11:47.137] 2019/10/03 22:11:47 azure.go:232: Reading credentials file /etc/azure-cred/credentials W1003 22:11:47.144] 2019/10/03 22:11:47 process.go:153: Running: make -C /go/src/k8s.io/kubernetes bazel-release I1003 22:11:47.245] make: Entering directory '/go/src/k8s.io/kubernetes' W1003 22:11:47.346] Extracting Bazel installation... W1003 22:12:12.332] Starting local Bazel server and connecting to it... W1003 22:12:14.230] Loading: W1003 22:12:14.233] Loading: 0 packages loaded W1003 22:12:15.236] Loading: 0 packages loaded W1003 22:12:16.846] Loading: 0 packages loaded W1003 22:12:18.244] Loading: 0 packages loaded W1003 22:12:20.321] Loading: 0 packages loaded W1003 22:12:21.434] Loading: 0 packages loaded W1003 22:12:21.434] currently loading: build/release-tars W1003 22:12:23.366] Loading: 0 packages loaded W1003 22:12:23.366] currently loading: build/release-tars W1003 22:12:24.411] Analyzing: target //build/release-tars:release-tars (1 packages loaded, 0 targets configured) W1003 22:12:25.980] Analyzing: target //build/release-tars:release-tars (59 packages loaded, 600 targets configured) W1003 22:12:27.768] Analyzing: target //build/release-tars:release-tars (703 packages loaded, 2851 targets configured) W1003 22:12:29.828] Analyzing: target //build/release-tars:release-tars (1426 packages loaded, 7695 targets configured) W1003 22:12:32.191] Analyzing: target //build/release-tars:release-tars (2000 packages loaded, 12764 targets configured) W1003 22:12:34.910] Analyzing: target //build/release-tars:release-tars (2812 packages loaded, 22974 targets configured) W1003 22:12:38.339] Analyzing: target //build/release-tars:release-tars (3027 packages loaded, 27105 targets configured) W1003 22:12:41.977] Analyzing: target //build/release-tars:release-tars (3064 packages loaded, 33629 targets configured) W1003 22:12:47.134] Analyzing: target //build/release-tars:release-tars (3071 packages loaded, 34565 targets configured) W1003 22:12:55.301] Analyzing: target //build/release-tars:release-tars (3072 packages loaded, 38922 targets configured) W1003 22:13:07.038] INFO: Analysed target //build/release-tars:release-tars (3072 packages loaded, 42245 targets configured). W1003 22:13:07.041] Building: checking cached actions W1003 22:13:07.041] INFO: Found 1 target... W1003 22:13:10.130] [0 / 18] [-----] Writing file cluster/addons/addons.args W1003 22:13:18.554] [133 / 5,296] GoCompile vendor/github.com/coredns/corefile-migration/migration/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/coredns/corefile-migration/migration.a; 3s linux-sandbox ... (7 actions, 5 running) W1003 22:13:28.249] [431 / 5,296] GoLink vendor/github.com/go-bindata/go-bindata/go-bindata/linux_amd64_stripped/go-bindata [for host]; 2s linux-sandbox ... (8 actions, 7 running) W1003 22:13:41.118] [591 / 5,296] GoCompile vendor/github.com/globalsign/mgo/bson/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/globalsign/mgo/bson.a; 2s linux-sandbox ... (8 actions, 7 running) W1003 22:13:54.250] [686 / 5,296] GoCompile vendor/gonum.org/v1/gonum/blas/gonum/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/gonum.org/v1/gonum/blas/gonum.a; 3s linux-sandbox ... (8 actions, 7 running) W1003 22:14:09.676] [830 / 5,296] GoCompile vendor/github.com/vmware/govmomi/vim25/types/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/types.a; 7s linux-sandbox ... (8 actions, 7 running) W1003 22:14:27.960] [1,079 / 5,296] PackageTar build/release-tars/kubernetes.tar.gz; 1s linux-sandbox ... (7 actions running) W1003 22:14:48.195] [1,422 / 5,296] GoCompile vendor/github.com/gophercloud/gophercloud/openstack/networking/v2/extensions/lbaas_v2/pools/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/gophercloud/gophercloud/openstack/networking/v2/extensions/lbaas_v2/pools.a; 0s linux-sandbox ... (8 actions, 7 running) W1003 22:15:11.481] [1,558 / 5,296] GoCompile vendor/github.com/vishvananda/netlink/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vishvananda/netlink.a~partial.a; 3s linux-sandbox ... (8 actions, 7 running) W1003 22:15:38.145] [1,699 / 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; 6s linux-sandbox ... (8 actions, 7 running) W1003 22:16:09.768] [1,857 / 5,296] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 21s linux-sandbox ... (8 actions, 7 running) W1003 22:16:46.002] [1,951 / 5,296] ; 24s linux-sandbox ... (8 actions running) W1003 22:17:27.039] [2,157 / 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; 9s linux-sandbox ... (8 actions running) W1003 22:18:15.684] [2,412 / 5,296] GoCompile vendor/golang.org/x/crypto/ssh/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/golang.org/x/crypto/ssh.a; 3s linux-sandbox ... (8 actions, 7 running) W1003 22:19:09.925] [2,708 / 5,296] GoCompile vendor/golang.org/x/net/http2/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/golang.org/x/net/http2.a; 2s linux-sandbox ... (8 actions, 7 running) W1003 22:20:12.606] [3,032 / 5,296] GoCompile staging/src/k8s.io/api/extensions/v1beta1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/api/extensions/v1beta1.a; 1s linux-sandbox ... (8 actions, 7 running) W1003 22:21:24.390] [3,485 / 5,296] GoCompile cmd/kubeadm/app/util/apiclient/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/cmd/kubeadm/app/util/apiclient.a; 2s linux-sandbox ... (8 actions, 7 running) W1003 22:22:47.033] [3,869 / 5,296] GoLink cmd/kubectl/linux_amd64_pure_stripped/kubectl; 8s linux-sandbox ... (8 actions, 7 running) W1003 22:24:22.254] [4,243 / 5,296] GoLink cmd/kube-scheduler/linux_amd64_pure_stripped/kube-scheduler; 24s linux-sandbox ... (8 actions, 7 running) W1003 22:26:12.966] [4,684 / 5,296] GZIP build/kube-controller-manager-internal-layer.tar.gz; 22s linux-sandbox ... (7 actions, 6 running) W1003 22:28:18.986] [5,005 / 5,296] GoCompile pkg/controller/statefulset/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/pkg/controller/statefulset.a; 0s linux-sandbox ... (8 actions, 7 running) W1003 22:30:48.685] [5,285 / 5,296] GoLink cmd/genkubedocs/genkubedocs; 59s linux-sandbox ... (5 actions running) W1003 22:33:43.369] [5,294 / 5,296] PackageTar build/release-tars/kubernetes-test-linux-amd64.tar.gz; 49s linux-sandbox ... (2 actions running) W1003 22:33:50.466] Target //build/release-tars:release-tars up-to-date: W1003 22:33:50.466] bazel-bin/build/release-tars/kubernetes-client-linux-amd64.tar.gz W1003 22:33:50.466] bazel-bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz W1003 22:33:50.467] bazel-bin/build/release-tars/kubernetes-server-linux-amd64.tar.gz W1003 22:33:50.467] bazel-bin/build/release-tars/kubernetes-manifests.tar.gz W1003 22:33:50.467] bazel-bin/build/release-tars/kubernetes-test-portable.tar.gz W1003 22:33:50.467] bazel-bin/build/release-tars/kubernetes-test-linux-amd64.tar.gz W1003 22:33:50.467] bazel-bin/build/release-tars/kubernetes.tar.gz W1003 22:33:50.467] bazel-bin/build/release-tars/kubernetes-src.tar.gz W1003 22:33:50.517] INFO: Elapsed time: 1323.237s, Critical Path: 392.95s W1003 22:33:50.517] INFO: 5205 processes: 5205 linux-sandbox. W1003 22:33:50.524] INFO: Build completed successfully, 5296 total actions W1003 22:33:50.530] INFO: Build completed successfully, 5296 total actions W1003 22:33:50.540] 2019/10/03 22:33:50 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes bazel-release' finished in 22m3.393296368s W1003 22:33:50.540] 2019/10/03 22:33:50 util.go:277: Flushing memory. I1003 22:33:50.640] make: Leaving directory '/go/src/k8s.io/kubernetes' W1003 22:34:00.363] 2019/10/03 22:34:00 azure.go:901: Deleting resource group: kubetest-ca77b650-e62a-11e9-8665-024276f6d56b. W1003 22:34:00.827] 2019/10/03 22:34:00 azure.go:782: downloading /workspace/aks070243480/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json. W1003 22:34:00.827] 2019/10/03 22:34:00 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json W1003 22:34:01.034] 2019/10/03 22:34:01 azure.go:529: downloading /workspace/aks-engine.tar.gz from https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz. W1003 22:34:01.034] 2019/10/03 22:34:01 util.go:42: curl https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz W1003 22:34:02.342] 2019/10/03 22:34:02 azure.go:556: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes . W1003 22:34:02.346] 2019/10/03 22:34:02 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1 W1003 22:34:02.514] 2019/10/03 22:34:02 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 167.801695ms W1003 22:34:02.514] 2019/10/03 22:34:02 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks070243480/kubernetes.json --output-directory /workspace/aks070243480 I1003 22:34:02.724] INFO[0000] Generating assets into /workspace/aks070243480... W1003 22:34:13.061] 2019/10/03 22:34:13 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks070243480/kubernetes.json --output-directory /workspace/aks070243480' finished in 10.54652824s W1003 22:34:13.065] 2019/10/03 22:34:13 azure.go:627: Setting kubeconfig env variable: kubeconfig path: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json. W1003 22:34:13.065] 2019/10/03 22:34:13 azure.go:629: Creating resource group: kubetest-ca77b650-e62a-11e9-8665-024276f6d56b. W1003 22:34:13.065] 2019/10/03 22:34:13 azure.go:631: Creating Azure resource group: kubetest-ca77b650-e62a-11e9-8665-024276f6d56b for cluster deployment. W1003 22:34:14.704] 2019/10/03 22:34:14 azure.go:636: Validating deployment ARM templates. W1003 22:34:16.305] 2019/10/03 22:34:16 azure.go:642: Deploying cluster kubetest-ca77b650-e62a-11e9-8665-024276f6d56b in resource group kubetest-ca77b650-e62a-11e9-8665-024276f6d56b. W1003 22:45:24.425] 2019/10/03 22:45:24 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version W1003 22:45:25.082] 2019/10/03 22:45:25 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 657.027562ms W1003 22:45:25.082] 2019/10/03 22:45:25 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false get nodes -oyaml W1003 22:45:26.397] 2019/10/03 22:45:26 process.go:155: Step './cluster/kubectl.sh --match-server-version=false get nodes -oyaml' finished in 1.314216324s W1003 22:45:26.398] 2019/10/03 22:45:26 azure.go:945: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos. W1003 22:45:26.398] 2019/10/03 22:45:26 azure.go:945: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos. W1003 22:45:26.398] 2019/10/03 22:45:26 process.go:153: Running: kubectl get nodes --no-headers W1003 22:45:26.985] 2019/10/03 22:45:26 process.go:155: Step 'kubectl get nodes --no-headers' finished in 587.650827ms W1003 22:45:26.985] 2019/10/03 22:45:26 e2e.go:462: Cluster nodes: W1003 22:45:26.985] k8s-agentpool1-20660773-0 Ready agent 58s v1.15.0 W1003 22:45:26.986] k8s-agentpool1-20660773-1 Ready agent 82s v1.15.0 W1003 22:45:26.986] k8s-master-20660773-0 Ready master 2m22s v1.15.0 W1003 22:45:26.986] 2019/10/03 22:45:26 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version W1003 22:45:27.423] 2019/10/03 22:45:27 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 437.565771ms W1003 22:45:27.423] 2019/10/03 22:45:27 process.go:153: Running: make e2e-test I1003 22:45:27.523] go test -v -timeout=30m ./test/e2e "-ginkgo.noColor" I1003 22:46:18.130] Oct 3 22:46:18.129: INFO: The --provider flag is not set. Continuing as if --provider=skeleton had been used. I1003 22:46:18.130] === RUN TestE2E I1003 22:46:18.130] Running Suite: AzureDisk CSI Driver End-to-End Tests I1003 22:46:18.130] ==================================================== I1003 22:46:18.130] Random Seed: 1570142778 - Will randomize all specs I1003 22:46:18.131] Will run 9 of 9 specs I1003 22:46:18.131] I1003 22:46:20.016] 2019/10/03 22:46:20 Attempting docker login with Azure service principal I1003 22:46:21.288] 2019/10/03 22:46:21 docker login is successful I1003 22:46:21.288] 2019/10/03 22:46:21 Installing Azure Disk CSI Driver... I1003 22:46:21.289] make[1]: Entering directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver' I1003 22:46:21.291] # Use v2.11.0 helm to match tiller's version in clusters made by aks-engine I1003 22:46:21.292] curl https://raw.githubusercontent.com/helm/helm/master/scripts/get | DESIRED_VERSION=v2.11.0 bash I1003 22:46:21.364] % Total % Received % Xferd Average Speed Time Time Time Current I1003 22:46:21.364] Dload Upload Total Spent Left Speed I1003 22:46:21.424] 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 7034 100 7034 0 0 113k 0 --:--:-- --:--:-- --:--:-- 114k I1003 22:46:21.440] Downloading https://get.helm.sh/helm-v2.11.0-linux-amd64.tar.gz I1003 22:46:22.368] Preparing to install helm and tiller into /usr/local/bin I1003 22:46:22.397] helm installed into /usr/local/bin/helm I1003 22:46:22.425] tiller installed into /usr/local/bin/tiller I1003 22:46:22.460] Run 'helm init' to configure helm. I1003 22:46:22.476] # Make sure tiller is ready I1003 22:46:22.477] kubectl wait pod -l name=tiller --namespace kube-system --for condition=ready --timeout 5m I1003 22:46:23.012] pod/tiller-deploy-54c96cb5df-bkf9j condition met I1003 22:46:23.014] helm version I1003 22:46:23.064] Client: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1003 22:46:23.964] Server: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1003 22:46:23.966] # Only build and push the image if it does not exist in the registry I1003 22:46:23.967] docker pull k8sprowinternal.azurecr.io/azuredisk-csi:e2e-2de810f9504b359da5ad074573d8f3450ba10eeb || make azuredisk-container push I1003 22:46:24.188] Error response from daemon: manifest for k8sprowinternal.azurecr.io/azuredisk-csi:e2e-2de810f9504b359da5ad074573d8f3450ba10eeb not found I1003 22:46:24.192] make[2]: Entering directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver' I1003 22:46:24.199] if [ ! -d ./vendor ]; then dep ensure -vendor-only; fi I1003 22:46:24.200] CGO_ENABLED=0 GOOS=linux go build -a -ldflags "-X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.driverVersion=e2e-2de810f9504b359da5ad074573d8f3450ba10eeb -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.gitCommit=2de810f9504b359da5ad074573d8f3450ba10eeb -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.buildDate=2019-10-03T22:46:24Z -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.DriverName=disk.csi.azure.com -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.topologyKey=topology.disk.csi.azure.com/zone -extldflags "-static"" -o _output/azurediskplugin ./pkg/azurediskplugin I1003 22:47:01.011] docker build --no-cache -t k8sprowinternal.azurecr.io/azuredisk-csi:e2e-2de810f9504b359da5ad074573d8f3450ba10eeb -f ./pkg/azurediskplugin/Dockerfile . I1003 22:47:02.863] Sending build context to Docker daemon 187.1MB I1003 22:47:02.887] Step 1/6 : FROM debian:9 I1003 22:47:03.867] 9: Pulling from library/debian I1003 22:47:04.195] 092586df9206: Pulling fs layer I1003 22:47:05.068] 092586df9206: Verifying Checksum I1003 22:47:05.069] 092586df9206: Download complete I1003 22:47:08.203] 092586df9206: Pull complete I1003 22:47:08.226] Digest: sha256:5fb93ce7a427b7c1c2374d5c29d68a159de7d5e781deeda422f8d51a1a9b6480 I1003 22:47:08.245] Status: Downloaded newer image for debian:9 I1003 22:47:08.246] ---> cb15ecf641ad I1003 22:47:08.246] Step 2/6 : RUN apt-get update && apt-get install -y util-linux e2fsprogs mount ca-certificates udev xfsprogs I1003 22:47:13.326] ---> Running in 397cbc45c9c5 I1003 22:47:14.503] Get:1 http://security-cdn.debian.org/debian-security stretch/updates InRelease [94.3 kB] I1003 22:47:14.615] Get:3 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 Packages [499 kB] I1003 22:47:14.637] Ign:2 http://cdn-fastly.deb.debian.org/debian stretch InRelease I1003 22:47:14.746] Get:4 http://cdn-fastly.deb.debian.org/debian stretch-updates InRelease [91.0 kB] I1003 22:47:14.847] Get:5 http://cdn-fastly.deb.debian.org/debian stretch-updates/main amd64 Packages [27.4 kB] I1003 22:47:14.895] Get:6 http://cdn-fastly.deb.debian.org/debian stretch Release [118 kB] I1003 22:47:14.905] Get:7 http://cdn-fastly.deb.debian.org/debian stretch Release.gpg [2365 B] I1003 22:47:15.000] Get:8 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 Packages [7086 kB] I1003 22:47:16.168] Fetched 7918 kB in 1s (4119 kB/s) I1003 22:47:16.764] Reading package lists... I1003 22:47:17.418] Reading package lists... I1003 22:47:17.524] Building dependency tree... I1003 22:47:17.524] Reading state information... I1003 22:47:17.588] mount is already the newest version (2.29.2-1+deb9u1). I1003 22:47:17.588] mount set to manually installed. I1003 22:47:17.588] util-linux is already the newest version (2.29.2-1+deb9u1). I1003 22:47:17.588] util-linux set to manually installed. I1003 22:47:17.588] The following additional packages will be installed: I1003 22:47:17.589] e2fslibs libgpm2 libkmod2 libncurses5 libprocps6 libreadline5 libssl1.1 I1003 22:47:17.589] openssl procps psmisc readline-common I1003 22:47:17.589] Suggested packages: I1003 22:47:17.589] gpart parted fuse2fs e2fsck-static gpm readline-doc xfsdump acl attr quota I1003 22:47:17.707] The following NEW packages will be installed: I1003 22:47:17.708] ca-certificates libgpm2 libkmod2 libncurses5 libprocps6 libreadline5 I1003 22:47:17.708] libssl1.1 openssl procps psmisc readline-common udev xfsprogs I1003 22:47:17.708] The following packages will be upgraded: I1003 22:47:17.708] e2fslibs e2fsprogs I1003 22:47:17.892] 2 upgraded, 13 newly installed, 0 to remove and 3 not upgraded. I1003 22:47:17.893] Need to get 6166 kB of archives. I1003 22:47:17.893] After this operation, 19.5 MB of additional disk space will be used. I1003 22:47:17.893] Get:1 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libkmod2 amd64 23-2 [48.1 kB] I1003 22:47:17.895] Get:2 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 e2fslibs amd64 1.43.4-2+deb9u1 [208 kB] I1003 22:47:17.952] Get:3 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libncurses5 amd64 6.0+20161126-1+deb9u2 [93.4 kB] I1003 22:47:17.956] Get:12 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 e2fsprogs amd64 1.43.4-2+deb9u1 [947 kB] I1003 22:47:17.963] Get:4 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libprocps6 amd64 2:3.3.12-3+deb9u1 [58.5 kB] I1003 22:47:17.965] Get:5 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 procps amd64 2:3.3.12-3+deb9u1 [250 kB] I1003 22:47:17.971] Get:6 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 udev amd64 232-25+deb9u12 [1113 kB] I1003 22:47:17.978] Get:13 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 libssl1.1 amd64 1.1.0l-1~deb9u1 [1358 kB] I1003 22:47:17.992] Get:7 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 readline-common all 7.0-3 [70.4 kB] I1003 22:47:17.994] Get:8 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libgpm2 amd64 1.20.4-6.2+b1 [34.2 kB] I1003 22:47:17.994] Get:9 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 ca-certificates all 20161130+nmu1+deb9u1 [182 kB] I1003 22:47:17.997] Get:10 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libreadline5 amd64 5.2+dfsg-3+b1 [119 kB] I1003 22:47:17.999] Get:11 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 psmisc amd64 22.21-2.1+b2 [123 kB] I1003 22:47:18.000] Get:14 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 openssl amd64 1.1.0l-1~deb9u1 [749 kB] I1003 22:47:18.025] Get:15 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 xfsprogs amd64 4.9.0+nmu1 [811 kB] I1003 22:47:18.287] debconf: delaying package configuration, since apt-utils is not installed I1003 22:47:18.300] Fetched 6166 kB in 0s (19.4 MB/s) I1003 22:47:18.371] (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 6500 files and directories currently installed.) I1003 22:47:18.372] Preparing to unpack .../e2fslibs_1.43.4-2+deb9u1_amd64.deb ... I1003 22:47:18.439] Unpacking e2fslibs:amd64 (1.43.4-2+deb9u1) over (1.43.4-2) ... I1003 22:47:18.646] Setting up e2fslibs:amd64 (1.43.4-2+deb9u1) ... I1003 22:47:18.774] (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 6500 files and directories currently installed.) I1003 22:47:18.774] Preparing to unpack .../e2fsprogs_1.43.4-2+deb9u1_amd64.deb ... I1003 22:47:18.821] Unpacking e2fsprogs (1.43.4-2+deb9u1) over (1.43.4-2) ... I1003 22:47:19.987] Setting up e2fsprogs (1.43.4-2+deb9u1) ... I1003 22:47:20.149] Selecting previously unselected package libkmod2:amd64. I1003 22:47:20.153] (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 6500 files and directories currently installed.) I1003 22:47:20.153] Preparing to unpack .../00-libkmod2_23-2_amd64.deb ... I1003 22:47:20.171] Unpacking libkmod2:amd64 (23-2) ... I1003 22:47:20.300] Selecting previously unselected package libncurses5:amd64. I1003 22:47:20.301] Preparing to unpack .../01-libncurses5_6.0+20161126-1+deb9u2_amd64.deb ... I1003 22:47:20.318] Unpacking libncurses5:amd64 (6.0+20161126-1+deb9u2) ... I1003 22:47:20.432] Selecting previously unselected package libprocps6:amd64. I1003 22:47:20.434] Preparing to unpack .../02-libprocps6_2%3a3.3.12-3+deb9u1_amd64.deb ... I1003 22:47:20.448] Unpacking libprocps6:amd64 (2:3.3.12-3+deb9u1) ... I1003 22:47:20.587] Selecting previously unselected package procps. I1003 22:47:20.588] Preparing to unpack .../03-procps_2%3a3.3.12-3+deb9u1_amd64.deb ... I1003 22:47:20.606] Unpacking procps (2:3.3.12-3+deb9u1) ... I1003 22:47:20.773] Selecting previously unselected package udev. I1003 22:47:20.774] Preparing to unpack .../04-udev_232-25+deb9u12_amd64.deb ... I1003 22:47:20.816] Unpacking udev (232-25+deb9u12) ... I1003 22:47:21.159] Selecting previously unselected package libssl1.1:amd64. I1003 22:47:21.160] Preparing to unpack .../05-libssl1.1_1.1.0l-1~deb9u1_amd64.deb ... I1003 22:47:21.176] Unpacking libssl1.1:amd64 (1.1.0l-1~deb9u1) ... I1003 22:47:21.436] Selecting previously unselected package readline-common. I1003 22:47:21.437] Preparing to unpack .../06-readline-common_7.0-3_all.deb ... I1003 22:47:21.452] Unpacking readline-common (7.0-3) ... I1003 22:47:21.564] Selecting previously unselected package libgpm2:amd64. I1003 22:47:21.565] Preparing to unpack .../07-libgpm2_1.20.4-6.2+b1_amd64.deb ... I1003 22:47:21.580] Unpacking libgpm2:amd64 (1.20.4-6.2+b1) ... I1003 22:47:21.688] Selecting previously unselected package openssl. I1003 22:47:21.689] Preparing to unpack .../08-openssl_1.1.0l-1~deb9u1_amd64.deb ... I1003 22:47:21.704] Unpacking openssl (1.1.0l-1~deb9u1) ... I1003 22:47:21.925] Selecting previously unselected package ca-certificates. I1003 22:47:21.926] Preparing to unpack .../09-ca-certificates_20161130+nmu1+deb9u1_all.deb ... I1003 22:47:21.945] Unpacking ca-certificates (20161130+nmu1+deb9u1) ... I1003 22:47:22.115] Selecting previously unselected package libreadline5:amd64. I1003 22:47:22.116] Preparing to unpack .../10-libreadline5_5.2+dfsg-3+b1_amd64.deb ... I1003 22:47:22.132] Unpacking libreadline5:amd64 (5.2+dfsg-3+b1) ... I1003 22:47:22.304] Selecting previously unselected package psmisc. I1003 22:47:22.306] Preparing to unpack .../11-psmisc_22.21-2.1+b2_amd64.deb ... I1003 22:47:22.323] Unpacking psmisc (22.21-2.1+b2) ... I1003 22:47:22.472] Selecting previously unselected package xfsprogs. I1003 22:47:22.473] Preparing to unpack .../12-xfsprogs_4.9.0+nmu1_amd64.deb ... I1003 22:47:22.494] Unpacking xfsprogs (4.9.0+nmu1) ... I1003 22:47:22.796] Setting up libncurses5:amd64 (6.0+20161126-1+deb9u2) ... I1003 22:47:22.850] Setting up readline-common (7.0-3) ... I1003 22:47:22.897] Setting up psmisc (22.21-2.1+b2) ... I1003 22:47:22.943] Setting up libgpm2:amd64 (1.20.4-6.2+b1) ... I1003 22:47:22.989] Setting up libprocps6:amd64 (2:3.3.12-3+deb9u1) ... I1003 22:47:23.036] Setting up libkmod2:amd64 (23-2) ... I1003 22:47:23.081] Setting up procps (2:3.3.12-3+deb9u1) ... I1003 22:47:23.164] update-alternatives: using /usr/bin/w.procps to provide /usr/bin/w (w) in auto mode I1003 22:47:23.199] Processing triggers for libc-bin (2.24-11+deb9u4) ... I1003 22:47:23.242] Setting up udev (232-25+deb9u12) ... I1003 22:47:23.607] Adding group `input' (GID 101) ... I1003 22:47:23.663] Done. I1003 22:47:23.668] invoke-rc.d: could not determine current runlevel I1003 22:47:23.671] invoke-rc.d: policy-rc.d denied execution of start. I1003 22:47:23.718] Setting up libssl1.1:amd64 (1.1.0l-1~deb9u1) ... I1003 22:47:23.846] debconf: unable to initialize frontend: Dialog I1003 22:47:23.846] debconf: (TERM is not set, so the dialog frontend is not usable.) I1003 22:47:23.846] debconf: falling back to frontend: Readline I1003 22:47:23.846] debconf: unable to initialize frontend: Readline I1003 22:47:23.847] debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.24.1 /usr/local/share/perl/5.24.1 /usr/lib/x86_64-linux-gnu/perl5/5.24 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.24 /usr/share/perl/5.24 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base .) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.) I1003 22:47:23.847] debconf: falling back to frontend: Teletype I1003 22:47:23.916] Setting up openssl (1.1.0l-1~deb9u1) ... I1003 22:47:23.975] Setting up libreadline5:amd64 (5.2+dfsg-3+b1) ... I1003 22:47:24.018] Setting up ca-certificates (20161130+nmu1+deb9u1) ... I1003 22:47:24.127] debconf: unable to initialize frontend: Dialog I1003 22:47:24.128] debconf: (TERM is not set, so the dialog frontend is not usable.) I1003 22:47:24.128] debconf: falling back to frontend: Readline I1003 22:47:24.128] debconf: unable to initialize frontend: Readline I1003 22:47:24.129] debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.24.1 /usr/local/share/perl/5.24.1 /usr/lib/x86_64-linux-gnu/perl5/5.24 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.24 /usr/share/perl/5.24 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base .) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.) I1003 22:47:24.129] debconf: falling back to frontend: Teletype I1003 22:47:24.587] Updating certificates in /etc/ssl/certs... I1003 22:47:26.208] 151 added, 0 removed; done. I1003 22:47:26.324] Setting up xfsprogs (4.9.0+nmu1) ... I1003 22:47:26.380] Processing triggers for libc-bin (2.24-11+deb9u4) ... I1003 22:47:26.422] Processing triggers for ca-certificates (20161130+nmu1+deb9u1) ... I1003 22:47:26.440] Updating certificates in /etc/ssl/certs... I1003 22:47:26.909] 0 added, 0 removed; done. I1003 22:47:26.910] Running hooks in /etc/ca-certificates/update.d... I1003 22:47:26.910] done. I1003 22:47:29.669] Removing intermediate container 397cbc45c9c5 I1003 22:47:29.669] ---> af962e303682 I1003 22:47:29.669] Step 3/6 : LABEL maintainers="andyzhangx" I1003 22:47:30.257] ---> Running in e791863f98ce I1003 22:47:31.071] Removing intermediate container e791863f98ce I1003 22:47:31.071] ---> e0561fcea8d1 I1003 22:47:31.071] Step 4/6 : LABEL description="Azure Disk CSI Driver" I1003 22:47:31.261] ---> Running in 8d4de74dfd54 I1003 22:47:32.088] Removing intermediate container 8d4de74dfd54 I1003 22:47:32.088] ---> 8cc929566578 I1003 22:47:32.089] Step 5/6 : COPY ./_output/azurediskplugin /azurediskplugin I1003 22:47:34.565] ---> 2b25dbde57ab I1003 22:47:34.565] Step 6/6 : ENTRYPOINT ["/azurediskplugin"] I1003 22:47:34.722] ---> Running in 842765bf312d I1003 22:47:35.241] Removing intermediate container 842765bf312d I1003 22:47:35.242] ---> db66fba53674 I1003 22:47:35.358] Successfully built db66fba53674 I1003 22:47:35.511] Successfully tagged k8sprowinternal.azurecr.io/azuredisk-csi:e2e-2de810f9504b359da5ad074573d8f3450ba10eeb I1003 22:47:35.515] docker push k8sprowinternal.azurecr.io/azuredisk-csi:e2e-2de810f9504b359da5ad074573d8f3450ba10eeb I1003 22:47:35.572] The push refers to repository [k8sprowinternal.azurecr.io/azuredisk-csi] I1003 22:47:35.584] 255f1070114e: Preparing I1003 22:47:35.585] a17e59349be8: Preparing I1003 22:47:35.585] 55e6b89812f3: Preparing I1003 22:47:35.762] 55e6b89812f3: Layer already exists I1003 22:47:39.328] a17e59349be8: Pushed I1003 22:47:39.329] 255f1070114e: Pushed I1003 22:47:39.996] e2e-2de810f9504b359da5ad074573d8f3450ba10eeb: digest: sha256:351c6e65c0c4ab19400815240b1886bfe7378e5b32ce6a2c14dc227d4bbeab48 size: 953 I1003 22:47:40.008] make[2]: Leaving directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver' I1003 22:47:40.008] helm install charts/latest/azuredisk-csi-driver -n azuredisk-csi-driver --namespace kube-system --wait \ I1003 22:47:40.008] --set image.pullPolicy=IfNotPresent \ I1003 22:47:40.008] --set image.repository=k8sprowinternal.azurecr.io/azuredisk-csi \ I1003 22:47:40.008] --set image.tag=e2e-2de810f9504b359da5ad074573d8f3450ba10eeb I1003 22:48:31.431] NAME: azuredisk-csi-driver I1003 22:48:32.766] LAST DEPLOYED: Thu Oct 3 22:47:41 2019 I1003 22:48:32.767] NAMESPACE: kube-system I1003 22:48:32.767] STATUS: DEPLOYED I1003 22:48:32.767] I1003 22:48:32.767] RESOURCES: I1003 22:48:32.767] ==> v1/Service I1003 22:48:32.767] NAME AGE I1003 22:48:32.768] csi-azuredisk-controller 44s I1003 22:48:32.768] I1003 22:48:32.768] ==> v1/DaemonSet I1003 22:48:32.768] csi-azuredisk-node 44s I1003 22:48:32.768] I1003 22:48:32.768] ==> v1/Deployment I1003 22:48:32.768] csi-azuredisk-controller 44s I1003 22:48:32.768] I1003 22:48:32.768] ==> v1/Pod(related) I1003 22:48:32.768] I1003 22:48:32.769] NAME READY STATUS RESTARTS AGE I1003 22:48:32.769] csi-azuredisk-node-6c4jb 3/3 Running 0 44s I1003 22:48:32.769] csi-azuredisk-node-kwtzx 3/3 Running 0 44s I1003 22:48:32.769] csi-azuredisk-controller-7f8dccb9c6-cxr5x 6/6 Running 0 44s I1003 22:48:32.770] I1003 22:48:32.770] ==> v1/ServiceAccount I1003 22:48:32.770] I1003 22:48:32.770] NAME AGE I1003 22:48:32.770] csi-azuredisk-controller-sa 44s I1003 22:48:32.770] I1003 22:48:32.771] ==> v1beta1/CustomResourceDefinition I1003 22:48:32.771] csidrivers.csi.storage.k8s.io 44s I1003 22:48:32.771] csinodeinfos.csi.storage.k8s.io 44s I1003 22:48:32.771] I1003 22:48:32.771] ==> v1/ClusterRole I1003 22:48:32.771] azuredisk-external-attacher-role 44s I1003 22:48:32.772] azuredisk-cluster-driver-registrar-role 44s I1003 22:48:32.772] azuredisk-external-snapshotter-role 44s I1003 22:48:32.772] azuredisk-external-provisioner-role 44s I1003 22:48:32.772] I1003 22:48:32.772] ==> v1/ClusterRoleBinding I1003 22:48:32.773] azuredisk-csi-attacher-binding 44s I1003 22:48:32.773] azuredisk-csi-driver-registrar-binding 44s I1003 22:48:32.773] azuredisk-csi-snapshotter-binding 44s I1003 22:48:32.773] azuredisk-csi-provisioner-binding 44s I1003 22:48:32.773] I1003 22:48:32.774] I1003 22:48:32.774] NOTES: I1003 22:48:32.774] The Azure Disk CSI Driver is getting deployed to your cluster. I1003 22:48:32.774] I1003 22:48:32.774] To check Azure Disk CSI Driver pods status, please run: I1003 22:48:32.774] I1003 22:48:32.774] kubectl --namespace=kube-system get pods --selector="release=azuredisk-csi-driver" --watch I1003 22:48:32.775] I1003 22:48:32.775] make[1]: Leaving directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver' I1003 22:48:32.775] 2019/10/03 22:48:32 Azure Disk CSI Driver installed I1003 22:48:32.775] Dynamic Provisioning I1003 22:48:32.775] should delete PV with reclaimPolicy "Delete" I1003 22:48:32.776] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:177 I1003 22:48:32.776] [BeforeEach] Dynamic Provisioning I1003 22:48:32.776] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 22:48:32.776] STEP: Creating a kubernetes client I1003 22:48:32.776] Oct 3 22:48:32.770: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 22:48:32.776] STEP: Building a namespace api object, basename azuredisk I1003 22:48:33.354] Oct 3 22:48:33.353: INFO: Found PodSecurityPolicies; assuming PodSecurityPolicy is enabled. I1003 22:48:33.679] Oct 3 22:48:33.678: INFO: Found ClusterRoles; assuming RBAC is enabled. I1003 22:48:33.749] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-2149 I1003 22:48:33.991] STEP: Waiting for a default service account to be provisioned in namespace I1003 22:48:34.061] [BeforeEach] Dynamic Provisioning I1003 22:48:34.061] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 22:48:34.062] [It] should delete PV with reclaimPolicy "Delete" I1003 22:48:34.062] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:177 I1003 22:48:34.062] STEP: setting up the StorageClass I1003 22:48:34.062] STEP: creating a StorageClass I1003 22:48:34.132] STEP: setting up the PVC and PV I1003 22:48:34.133] STEP: creating a PVC I1003 22:48:34.205] STEP: waiting for PVC to be in phase "Bound" I1003 22:48:34.205] Oct 3 22:48:34.205: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-v2c7b] to have phase Bound I1003 22:48:34.275] Oct 3 22:48:34.275: INFO: PersistentVolumeClaim pvc-v2c7b found but phase is Pending instead of Bound. I1003 22:48:36.347] Oct 3 22:48:36.346: INFO: PersistentVolumeClaim pvc-v2c7b found but phase is Pending instead of Bound. I1003 22:48:38.418] Oct 3 22:48:38.417: INFO: PersistentVolumeClaim pvc-v2c7b found but phase is Pending instead of Bound. I1003 22:48:40.489] Oct 3 22:48:40.488: INFO: PersistentVolumeClaim pvc-v2c7b found but phase is Pending instead of Bound. I1003 22:48:42.560] Oct 3 22:48:42.560: INFO: PersistentVolumeClaim pvc-v2c7b found but phase is Pending instead of Bound. I1003 22:48:44.632] Oct 3 22:48:44.631: INFO: PersistentVolumeClaim pvc-v2c7b found but phase is Pending instead of Bound. I1003 22:48:46.702] Oct 3 22:48:46.702: INFO: PersistentVolumeClaim pvc-v2c7b found and phase=Bound (12.496920947s) I1003 22:48:46.702] STEP: checking the PVC I1003 22:48:46.772] STEP: validating provisioned PV I1003 22:48:46.843] STEP: checking the PV I1003 22:48:46.843] Oct 3 22:48:46.843: INFO: deleting PVC "azuredisk-2149"/"pvc-v2c7b" I1003 22:48:46.843] Oct 3 22:48:46.843: INFO: Deleting PersistentVolumeClaim "pvc-v2c7b" I1003 22:48:46.915] STEP: waiting for claim's PV "pvc-42e7fc8d-28de-4b31-9f10-02f75e367ece" to be deleted I1003 22:48:46.915] Oct 3 22:48:46.915: INFO: Waiting up to 10m0s for PersistentVolume pvc-42e7fc8d-28de-4b31-9f10-02f75e367ece to get deleted I1003 22:48:46.986] Oct 3 22:48:46.985: INFO: PersistentVolume pvc-42e7fc8d-28de-4b31-9f10-02f75e367ece found and phase=Released (70.467143ms) I1003 22:48:52.057] Oct 3 22:48:52.057: INFO: PersistentVolume pvc-42e7fc8d-28de-4b31-9f10-02f75e367ece found and phase=Released (5.141785s) I1003 22:48:57.128] Oct 3 22:48:57.128: INFO: PersistentVolume pvc-42e7fc8d-28de-4b31-9f10-02f75e367ece was removed I1003 22:48:57.129] Oct 3 22:48:57.128: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-2149 to be removed I1003 22:48:57.199] Oct 3 22:48:57.198: INFO: Claim "azuredisk-2149" in namespace "pvc-v2c7b" doesn't exist in the system I1003 22:48:57.199] [AfterEach] Dynamic Provisioning I1003 22:48:57.199] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 22:48:57.199] Oct 3 22:48:57.198: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 22:48:57.270] STEP: Destroying namespace "azuredisk-2149" for this suite. I1003 22:49:03.484] Oct 3 22:49:03.484: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 22:49:06.157] Oct 3 22:49:06.157: INFO: namespace azuredisk-2149 deletion completed in 8.887020843s I1003 22:49:06.157] I1003 22:49:06.157] • [SLOW TEST:33.387 seconds] I1003 22:49:06.157] Dynamic Provisioning I1003 22:49:06.158] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1003 22:49:06.158] should delete PV with reclaimPolicy "Delete" I1003 22:49:06.158] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:177 I1003 22:49:06.158] ------------------------------ I1003 22:49:06.158] Dynamic Provisioning I1003 22:49:06.158] should create a volume on demand I1003 22:49:06.159] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:45 I1003 22:49:06.159] [BeforeEach] Dynamic Provisioning I1003 22:49:06.159] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 22:49:06.159] STEP: Creating a kubernetes client I1003 22:49:06.159] Oct 3 22:49:06.157: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 22:49:06.160] STEP: Building a namespace api object, basename azuredisk I1003 22:49:06.369] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-9306 I1003 22:49:06.615] STEP: Waiting for a default service account to be provisioned in namespace I1003 22:49:06.685] [BeforeEach] Dynamic Provisioning I1003 22:49:06.685] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 22:49:06.685] [It] should create a volume on demand I1003 22:49:06.686] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:45 I1003 22:49:06.686] STEP: setting up the StorageClass I1003 22:49:06.686] STEP: creating a StorageClass I1003 22:49:06.759] STEP: setting up the PVC and PV I1003 22:49:06.759] STEP: creating a PVC I1003 22:49:06.832] STEP: waiting for PVC to be in phase "Bound" I1003 22:49:06.832] Oct 3 22:49:06.832: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-qrk88] to have phase Bound I1003 22:49:06.902] Oct 3 22:49:06.902: INFO: PersistentVolumeClaim pvc-qrk88 found but phase is Pending instead of Bound. I1003 22:49:08.973] Oct 3 22:49:08.972: INFO: PersistentVolumeClaim pvc-qrk88 found but phase is Pending instead of Bound. I1003 22:49:11.044] Oct 3 22:49:11.044: INFO: PersistentVolumeClaim pvc-qrk88 found but phase is Pending instead of Bound. I1003 22:49:13.115] Oct 3 22:49:13.115: INFO: PersistentVolumeClaim pvc-qrk88 found but phase is Pending instead of Bound. I1003 22:49:15.186] Oct 3 22:49:15.186: INFO: PersistentVolumeClaim pvc-qrk88 found but phase is Pending instead of Bound. I1003 22:49:17.257] Oct 3 22:49:17.257: INFO: PersistentVolumeClaim pvc-qrk88 found and phase=Bound (10.42526729s) I1003 22:49:17.257] STEP: checking the PVC I1003 22:49:17.328] STEP: validating provisioned PV I1003 22:49:17.399] STEP: checking the PV I1003 22:49:17.400] STEP: deploying the pod I1003 22:49:17.472] STEP: checking that the pods command exits with no error I1003 22:49:17.472] Oct 3 22:49:17.472: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-7nznt" in namespace "azuredisk-9306" to be "success or failure" I1003 22:49:17.543] Oct 3 22:49:17.543: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 70.798945ms I1003 22:49:19.614] Oct 3 22:49:19.614: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.142039197s I1003 22:49:21.692] Oct 3 22:49:21.692: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.220259502s I1003 22:49:23.764] Oct 3 22:49:23.763: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.291565054s I1003 22:49:25.838] Oct 3 22:49:25.838: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.365843928s I1003 22:49:27.914] Oct 3 22:49:27.914: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.441894317s I1003 22:49:29.985] Oct 3 22:49:29.985: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 12.512861866s I1003 22:49:32.056] Oct 3 22:49:32.056: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 14.584176518s I1003 22:49:34.128] Oct 3 22:49:34.128: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 16.655933373s I1003 22:49:36.199] Oct 3 22:49:36.199: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 18.727239824s I1003 22:49:38.271] Oct 3 22:49:38.270: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 20.798537576s I1003 22:49:40.342] Oct 3 22:49:40.342: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 22.869812827s I1003 22:49:42.413] Oct 3 22:49:42.413: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 24.941049878s I1003 22:49:44.484] Oct 3 22:49:44.484: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 27.012110528s I1003 22:49:46.555] Oct 3 22:49:46.555: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 29.083252078s I1003 22:49:48.627] Oct 3 22:49:48.626: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 31.15460473s I1003 22:49:50.698] Oct 3 22:49:50.698: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 33.226133783s I1003 22:49:52.769] Oct 3 22:49:52.769: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 35.297336734s I1003 22:49:54.841] Oct 3 22:49:54.840: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 37.368610185s I1003 22:49:56.911] Oct 3 22:49:56.911: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 39.439293231s I1003 22:49:58.982] Oct 3 22:49:58.982: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 41.509805476s I1003 22:50:01.052] Oct 3 22:50:01.052: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 43.580282721s I1003 22:50:03.124] Oct 3 22:50:03.123: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 45.651563472s I1003 22:50:05.195] Oct 3 22:50:05.195: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 47.722846223s I1003 22:50:07.266] Oct 3 22:50:07.266: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 49.794078674s I1003 22:50:09.338] Oct 3 22:50:09.338: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 51.865862229s I1003 22:50:11.409] Oct 3 22:50:11.409: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 53.93718858s I1003 22:50:13.480] Oct 3 22:50:13.480: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 56.008461331s I1003 22:50:15.552] Oct 3 22:50:15.551: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 58.07960498s I1003 22:50:17.623] Oct 3 22:50:17.623: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 1m0.151076733s I1003 22:50:19.695] Oct 3 22:50:19.695: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 1m2.222730486s I1003 22:50:21.766] Oct 3 22:50:21.765: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 1m4.293670734s I1003 22:50:23.838] Oct 3 22:50:23.838: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 1m6.365917192s I1003 22:50:25.909] Oct 3 22:50:25.908: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Pending", Reason="", readiness=false. Elapsed: 1m8.436703939s I1003 22:50:27.980] Oct 3 22:50:27.980: INFO: Pod "azuredisk-volume-tester-7nznt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m10.508229092s I1003 22:50:27.981] STEP: Saw pod success I1003 22:50:27.981] Oct 3 22:50:27.980: INFO: Pod "azuredisk-volume-tester-7nznt" satisfied condition "success or failure" I1003 22:50:27.981] Oct 3 22:50:27.980: INFO: deleting Pod "azuredisk-9306"/"azuredisk-volume-tester-7nznt" I1003 22:50:28.084] Oct 3 22:50:28.083: INFO: Pod azuredisk-volume-tester-7nznt has the following logs: hello world I1003 22:50:28.084] I1003 22:50:28.084] STEP: Deleting pod azuredisk-volume-tester-7nznt in namespace azuredisk-9306 I1003 22:50:28.161] Oct 3 22:50:28.161: INFO: deleting PVC "azuredisk-9306"/"pvc-qrk88" I1003 22:50:28.161] Oct 3 22:50:28.161: INFO: Deleting PersistentVolumeClaim "pvc-qrk88" I1003 22:50:28.233] STEP: waiting for claim's PV "pvc-8ad1665d-8889-40aa-9d65-25bcd1416181" to be deleted I1003 22:50:28.233] Oct 3 22:50:28.233: INFO: Waiting up to 10m0s for PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 to get deleted I1003 22:50:28.304] Oct 3 22:50:28.303: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (70.452343ms) I1003 22:50:33.376] Oct 3 22:50:33.375: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (5.1423378s) I1003 22:50:38.447] Oct 3 22:50:38.447: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (10.213713154s) I1003 22:50:43.518] Oct 3 22:50:43.518: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (15.285116908s) I1003 22:50:48.589] Oct 3 22:50:48.589: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (20.355548954s) I1003 22:50:53.660] Oct 3 22:50:53.660: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (25.426808206s) I1003 22:50:58.732] Oct 3 22:50:58.731: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (30.49842276s) I1003 22:51:03.803] Oct 3 22:51:03.803: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (35.569826913s) I1003 22:51:08.875] Oct 3 22:51:08.875: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (40.642101473s) I1003 22:51:13.947] Oct 3 22:51:13.947: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (45.713532226s) I1003 22:51:19.019] Oct 3 22:51:19.019: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 found and phase=Released (50.785562083s) I1003 22:51:24.090] Oct 3 22:51:24.090: INFO: PersistentVolume pvc-8ad1665d-8889-40aa-9d65-25bcd1416181 was removed I1003 22:51:24.090] Oct 3 22:51:24.090: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-9306 to be removed I1003 22:51:24.161] Oct 3 22:51:24.160: INFO: Claim "azuredisk-9306" in namespace "pvc-qrk88" doesn't exist in the system I1003 22:51:24.161] Oct 3 22:51:24.161: INFO: deleting StorageClass azuredisk-9306-disk.csi.azure.com-dynamic-sc-cb5h4 I1003 22:51:24.234] [AfterEach] Dynamic Provisioning I1003 22:51:24.234] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 22:51:24.234] Oct 3 22:51:24.234: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 22:51:24.305] STEP: Destroying namespace "azuredisk-9306" for this suite. I1003 22:51:30.520] Oct 3 22:51:30.520: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 22:51:33.209] Oct 3 22:51:33.209: INFO: namespace azuredisk-9306 deletion completed in 8.903737463s I1003 22:51:33.209] I1003 22:51:33.209] • [SLOW TEST:147.052 seconds] I1003 22:51:33.209] Dynamic Provisioning I1003 22:51:33.210] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1003 22:51:33.210] should create a volume on demand I1003 22:51:33.210] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:45 I1003 22:51:33.210] ------------------------------ I1003 22:51:33.210] Dynamic Provisioning I1003 22:51:33.210] should create a raw block volume on demand I1003 22:51:33.211] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:67 I1003 22:51:33.211] [BeforeEach] Dynamic Provisioning I1003 22:51:33.211] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 22:51:33.211] STEP: Creating a kubernetes client I1003 22:51:33.211] Oct 3 22:51:33.209: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 22:51:33.211] STEP: Building a namespace api object, basename azuredisk I1003 22:51:33.421] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-6910 I1003 22:51:33.662] STEP: Waiting for a default service account to be provisioned in namespace I1003 22:51:33.732] [BeforeEach] Dynamic Provisioning I1003 22:51:33.732] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 22:51:33.733] [It] should create a raw block volume on demand I1003 22:51:33.733] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:67 I1003 22:51:33.733] STEP: setting up the StorageClass I1003 22:51:33.733] STEP: creating a StorageClass I1003 22:51:33.804] STEP: setting up the PVC and PV I1003 22:51:33.804] STEP: creating a PVC I1003 22:51:33.877] STEP: waiting for PVC to be in phase "Bound" I1003 22:51:33.878] Oct 3 22:51:33.877: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-9tnd9] to have phase Bound I1003 22:51:33.948] Oct 3 22:51:33.948: INFO: PersistentVolumeClaim pvc-9tnd9 found but phase is Pending instead of Bound. I1003 22:51:36.019] Oct 3 22:51:36.019: INFO: PersistentVolumeClaim pvc-9tnd9 found but phase is Pending instead of Bound. I1003 22:51:38.091] Oct 3 22:51:38.090: INFO: PersistentVolumeClaim pvc-9tnd9 found but phase is Pending instead of Bound. I1003 22:51:40.162] Oct 3 22:51:40.161: INFO: PersistentVolumeClaim pvc-9tnd9 found but phase is Pending instead of Bound. I1003 22:51:42.233] Oct 3 22:51:42.233: INFO: PersistentVolumeClaim pvc-9tnd9 found but phase is Pending instead of Bound. I1003 22:51:44.304] Oct 3 22:51:44.304: INFO: PersistentVolumeClaim pvc-9tnd9 found and phase=Bound (10.426375387s) I1003 22:51:44.304] STEP: checking the PVC I1003 22:51:44.375] STEP: validating provisioned PV I1003 22:51:44.446] STEP: checking the PV I1003 22:51:44.446] STEP: deploying the pod I1003 22:51:44.518] STEP: checking that the pods command exits with no error I1003 22:51:44.519] Oct 3 22:51:44.518: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-2p97f" in namespace "azuredisk-6910" to be "success or failure" I1003 22:51:44.589] Oct 3 22:51:44.589: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 70.624243ms I1003 22:51:46.661] Oct 3 22:51:46.661: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.142365497s I1003 22:51:48.733] Oct 3 22:51:48.733: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.214462352s I1003 22:51:50.805] Oct 3 22:51:50.804: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.286064104s I1003 22:51:52.876] Oct 3 22:51:52.876: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.357580956s I1003 22:51:54.948] Oct 3 22:51:54.947: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.429038306s I1003 22:51:57.021] Oct 3 22:51:57.021: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 12.502306271s I1003 22:51:59.093] Oct 3 22:51:59.093: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 14.574237526s I1003 22:52:01.164] Oct 3 22:52:01.164: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 16.645762777s I1003 22:52:03.236] Oct 3 22:52:03.236: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 18.717398729s I1003 22:52:05.308] Oct 3 22:52:05.308: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 20.789291183s I1003 22:52:07.379] Oct 3 22:52:07.379: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 22.86024063s I1003 22:52:09.451] Oct 3 22:52:09.450: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 24.932042883s I1003 22:52:11.522] Oct 3 22:52:11.521: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 27.002868329s I1003 22:52:13.593] Oct 3 22:52:13.593: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 29.074529681s I1003 22:52:15.665] Oct 3 22:52:15.665: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 31.146182033s I1003 22:52:17.736] Oct 3 22:52:17.736: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 33.217732384s I1003 22:52:19.808] Oct 3 22:52:19.808: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 35.289245435s I1003 22:52:21.880] Oct 3 22:52:21.880: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 37.361452891s I1003 22:52:23.952] Oct 3 22:52:23.952: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 39.433201744s I1003 22:52:26.024] Oct 3 22:52:26.024: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 41.505272199s I1003 22:52:28.095] Oct 3 22:52:28.095: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 43.57672145s I1003 22:52:30.167] Oct 3 22:52:30.167: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 45.648263301s I1003 22:52:32.241] Oct 3 22:52:32.241: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 47.722256471s I1003 22:52:34.312] Oct 3 22:52:34.312: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 49.793489819s I1003 22:52:36.384] Oct 3 22:52:36.384: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 51.865295172s I1003 22:52:38.455] Oct 3 22:52:38.455: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 53.936866523s I1003 22:52:40.527] Oct 3 22:52:40.526: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 56.00788187s I1003 22:52:42.598] Oct 3 22:52:42.598: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 58.079841224s I1003 22:52:44.670] Oct 3 22:52:44.670: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 1m0.151352875s I1003 22:52:46.741] Oct 3 22:52:46.741: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 1m2.222754525s I1003 22:52:48.813] Oct 3 22:52:48.813: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 1m4.294306076s I1003 22:52:50.885] Oct 3 22:52:50.885: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 1m6.366110428s I1003 22:52:52.955] Oct 3 22:52:52.955: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Pending", Reason="", readiness=false. Elapsed: 1m8.436870973s I1003 22:52:55.027] Oct 3 22:52:55.027: INFO: Pod "azuredisk-volume-tester-2p97f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m10.508110122s I1003 22:52:55.027] STEP: Saw pod success I1003 22:52:55.027] Oct 3 22:52:55.027: INFO: Pod "azuredisk-volume-tester-2p97f" satisfied condition "success or failure" I1003 22:52:55.027] Oct 3 22:52:55.027: INFO: deleting Pod "azuredisk-6910"/"azuredisk-volume-tester-2p97f" I1003 22:52:55.131] Oct 3 22:52:55.131: INFO: Pod azuredisk-volume-tester-2p97f has the following logs: e2e-test I1003 22:52:55.132] I1003 22:52:55.132] STEP: Deleting pod azuredisk-volume-tester-2p97f in namespace azuredisk-6910 I1003 22:52:55.208] Oct 3 22:52:55.208: INFO: deleting PVC "azuredisk-6910"/"pvc-9tnd9" I1003 22:52:55.208] Oct 3 22:52:55.208: INFO: Deleting PersistentVolumeClaim "pvc-9tnd9" I1003 22:52:55.279] STEP: waiting for claim's PV "pvc-183f311b-d77a-49db-8af7-438bae57b734" to be deleted I1003 22:52:55.279] Oct 3 22:52:55.279: INFO: Waiting up to 10m0s for PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 to get deleted I1003 22:52:55.350] Oct 3 22:52:55.349: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (70.214341ms) I1003 22:53:00.422] Oct 3 22:53:00.422: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5.142556898s) I1003 22:53:05.494] Oct 3 22:53:05.494: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (10.214627052s) I1003 22:53:10.565] Oct 3 22:53:10.565: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (15.2858013s) I1003 22:53:15.637] Oct 3 22:53:15.636: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (20.357269149s) I1003 22:53:20.716] Oct 3 22:53:20.716: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (25.437133763s) I1003 22:53:25.789] Oct 3 22:53:25.789: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (30.50964202s) I1003 22:53:30.860] Oct 3 22:53:30.860: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (35.580810967s) I1003 22:53:35.931] Oct 3 22:53:35.931: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (40.652220916s) I1003 22:53:41.003] Oct 3 22:53:41.003: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (45.723911266s) I1003 22:53:46.074] Oct 3 22:53:46.074: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (50.794971912s) I1003 22:53:51.150] Oct 3 22:53:51.150: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (55.870797694s) I1003 22:53:56.222] Oct 3 22:53:56.222: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m0.942939648s) I1003 22:54:01.294] Oct 3 22:54:01.293: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m6.014240295s) I1003 22:54:06.364] Oct 3 22:54:06.364: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m11.085077638s) I1003 22:54:11.436] Oct 3 22:54:11.435: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m16.156309084s) I1003 22:54:16.507] Oct 3 22:54:16.507: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m21.228179836s) I1003 22:54:21.579] Oct 3 22:54:21.579: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m26.299503782s) I1003 22:54:26.650] Oct 3 22:54:26.650: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m31.370603127s) I1003 22:54:31.721] Oct 3 22:54:31.721: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m36.441903174s) I1003 22:54:36.792] Oct 3 22:54:36.792: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m41.513138619s) I1003 22:54:41.867] Oct 3 22:54:41.867: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m46.587949693s) I1003 22:54:46.938] Oct 3 22:54:46.938: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m51.659086337s) I1003 22:54:52.018] Oct 3 22:54:52.018: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (1m56.739139251s) I1003 22:54:57.092] Oct 3 22:54:57.092: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m1.813209318s) I1003 22:55:02.164] Oct 3 22:55:02.164: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m6.884898567s) I1003 22:55:07.236] Oct 3 22:55:07.236: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m11.957104619s) I1003 22:55:12.309] Oct 3 22:55:12.309: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m17.029576974s) I1003 22:55:17.381] Oct 3 22:55:17.381: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m22.101831326s) I1003 22:55:22.454] Oct 3 22:55:22.453: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m27.17417788s) I1003 22:55:27.526] Oct 3 22:55:27.525: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m32.246427732s) I1003 22:55:32.598] Oct 3 22:55:32.598: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m37.318911886s) I1003 22:55:37.669] Oct 3 22:55:37.669: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m42.39004903s) I1003 22:55:42.742] Oct 3 22:55:42.741: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m47.462246182s) I1003 22:55:47.814] Oct 3 22:55:47.813: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m52.534380433s) I1003 22:55:52.886] Oct 3 22:55:52.886: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (2m57.606939087s) I1003 22:55:57.959] Oct 3 22:55:57.958: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m2.67932974s) I1003 22:56:03.031] Oct 3 22:56:03.030: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m7.75124829s) I1003 22:56:08.103] Oct 3 22:56:08.102: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m12.823208639s) I1003 22:56:13.175] Oct 3 22:56:13.175: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m17.895476491s) I1003 22:56:18.247] Oct 3 22:56:18.247: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m22.968056545s) I1003 22:56:23.320] Oct 3 22:56:23.319: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m28.040232196s) I1003 22:56:28.391] Oct 3 22:56:28.391: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m33.111882743s) I1003 22:56:33.463] Oct 3 22:56:33.463: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m38.18365689s) I1003 22:56:38.541] Oct 3 22:56:38.534: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m43.254985134s) I1003 22:56:43.606] Oct 3 22:56:43.606: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m48.326978183s) I1003 22:56:48.679] Oct 3 22:56:48.678: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m53.399220134s) I1003 22:56:53.751] Oct 3 22:56:53.751: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (3m58.471503885s) I1003 22:56:58.822] Oct 3 22:56:58.822: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m3.543072231s) I1003 22:57:03.894] Oct 3 22:57:03.894: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m8.615042179s) I1003 22:57:08.966] Oct 3 22:57:08.966: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m13.686596325s) I1003 22:57:14.038] Oct 3 22:57:14.038: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m18.758581173s) I1003 22:57:19.111] Oct 3 22:57:19.111: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m23.831560729s) I1003 22:57:24.183] Oct 3 22:57:24.183: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m28.903712947s) I1003 22:57:29.255] Oct 3 22:57:29.255: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m33.975935927s) I1003 22:57:34.330] Oct 3 22:57:34.330: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m39.050597617s) I1003 22:57:39.402] Oct 3 22:57:39.402: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m44.122714377s) I1003 22:57:44.474] Oct 3 22:57:44.474: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m49.195156731s) I1003 22:57:49.547] Oct 3 22:57:49.546: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m54.267322374s) I1003 22:57:54.619] Oct 3 22:57:54.618: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (4m59.339418807s) I1003 22:57:59.690] Oct 3 22:57:59.690: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m4.411217928s) I1003 22:58:04.765] Oct 3 22:58:04.765: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m9.485871663s) I1003 22:58:09.837] Oct 3 22:58:09.837: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m14.557672467s) I1003 22:58:14.909] Oct 3 22:58:14.908: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m19.629352962s) I1003 22:58:19.982] Oct 3 22:58:19.981: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m24.702146056s) I1003 22:58:25.054] Oct 3 22:58:25.054: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m29.775089643s) I1003 22:58:30.127] Oct 3 22:58:30.126: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m34.847174115s) I1003 22:58:35.198] Oct 3 22:58:35.198: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m39.919046876s) I1003 22:58:40.270] Oct 3 22:58:40.270: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m44.990803829s) I1003 22:58:45.343] Oct 3 22:58:45.342: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m50.063372879s) I1003 22:58:50.415] Oct 3 22:58:50.415: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (5m55.135462018s) I1003 22:58:55.487] Oct 3 22:58:55.487: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m0.207510648s) I1003 22:59:00.559] Oct 3 22:59:00.558: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m5.279377569s) I1003 22:59:05.631] Oct 3 22:59:05.630: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m10.351165182s) I1003 22:59:10.703] Oct 3 22:59:10.702: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m15.423312989s) I1003 22:59:15.775] Oct 3 22:59:15.775: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m20.495905993s) I1003 22:59:20.848] Oct 3 22:59:20.847: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m25.568254586s) I1003 22:59:25.921] Oct 3 22:59:25.920: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m30.641382378s) I1003 22:59:30.992] Oct 3 22:59:30.992: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m35.71282885s) I1003 22:59:36.064] Oct 3 22:59:36.064: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m40.784790818s) I1003 22:59:41.138] Oct 3 22:59:41.138: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m45.859005996s) I1003 22:59:46.211] Oct 3 22:59:46.211: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m50.931524254s) I1003 22:59:51.283] Oct 3 22:59:51.283: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (6m56.003591001s) I1003 22:59:56.355] Oct 3 22:59:56.355: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m1.076034044s) I1003 23:00:01.427] Oct 3 23:00:01.427: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m6.147883175s) I1003 23:00:06.499] Oct 3 23:00:06.499: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m11.219685298s) I1003 23:00:11.571] Oct 3 23:00:11.571: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m16.291798418s) I1003 23:00:16.643] Oct 3 23:00:16.642: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m21.363238325s) I1003 23:00:21.714] Oct 3 23:00:21.714: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m26.434998927s) I1003 23:00:26.787] Oct 3 23:00:26.786: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m31.507247927s) I1003 23:00:31.859] Oct 3 23:00:31.858: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m36.579376719s) I1003 23:00:36.931] Oct 3 23:00:36.931: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m41.651688606s) I1003 23:00:42.004] Oct 3 23:00:42.003: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m46.724281389s) I1003 23:00:47.076] Oct 3 23:00:47.076: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 found and phase=Released (7m51.796723564s) I1003 23:00:52.149] Oct 3 23:00:52.149: INFO: PersistentVolume pvc-183f311b-d77a-49db-8af7-438bae57b734 was removed I1003 23:00:52.149] Oct 3 23:00:52.149: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-6910 to be removed I1003 23:00:52.220] Oct 3 23:00:52.220: INFO: Claim "azuredisk-6910" in namespace "pvc-9tnd9" doesn't exist in the system I1003 23:00:52.220] Oct 3 23:00:52.220: INFO: deleting StorageClass azuredisk-6910-disk.csi.azure.com-dynamic-sc-rlhkc I1003 23:00:52.294] [AfterEach] Dynamic Provisioning I1003 23:00:52.295] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:00:52.295] Oct 3 23:00:52.294: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:00:52.435] STEP: Destroying namespace "azuredisk-6910" for this suite. I1003 23:00:58.656] Oct 3 23:00:58.656: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 23:01:01.357] Oct 3 23:01:01.357: INFO: namespace azuredisk-6910 deletion completed in 8.921823009s I1003 23:01:01.357] I1003 23:01:01.357] • [SLOW TEST:568.148 seconds] I1003 23:01:01.358] Dynamic Provisioning I1003 23:01:01.358] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1003 23:01:01.358] should create a raw block volume on demand I1003 23:01:01.358] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:67 I1003 23:01:01.359] ------------------------------ I1003 23:01:01.359] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:01:01.359] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1003 23:01:01.359] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:66 I1003 23:01:01.360] [BeforeEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:01:01.360] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 23:01:01.360] STEP: Creating a kubernetes client I1003 23:01:01.360] Oct 3 23:01:01.357: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 23:01:01.361] STEP: Building a namespace api object, basename azuredisk I1003 23:01:01.575] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-1268 I1003 23:01:01.817] STEP: Waiting for a default service account to be provisioned in namespace I1003 23:01:01.887] [BeforeEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:01:01.888] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:48 I1003 23:01:01.888] [It] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1003 23:01:01.888] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:66 I1003 23:01:08.799] STEP: Successfully provisioned AzureDisk volume: "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-ca77b650-e62a-11e9-8665-024276f6d56b/providers/Microsoft.Compute/disks/pre-provisioned-readOnly" I1003 23:01:08.800] I1003 23:01:08.800] STEP: setting up the PV I1003 23:01:08.800] STEP: creating a PV I1003 23:01:08.871] STEP: setting up the PVC I1003 23:01:08.872] STEP: creating a PVC I1003 23:01:08.946] STEP: waiting for PVC to be in phase "Bound" I1003 23:01:08.946] Oct 3 23:01:08.945: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-9tmsd] to have phase Bound I1003 23:01:09.018] Oct 3 23:01:09.018: INFO: PersistentVolumeClaim pvc-9tmsd found and phase=Bound (72.101166ms) I1003 23:01:09.018] STEP: checking the PVC I1003 23:01:09.090] STEP: validating provisioned PV I1003 23:01:09.161] STEP: checking the PV I1003 23:01:09.161] STEP: deploying the pod I1003 23:01:09.232] STEP: checking that the pods command exits with an error I1003 23:01:09.233] Oct 3 23:01:09.232: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-x585l" in namespace "azuredisk-1268" to be "Error status code" I1003 23:01:09.304] Oct 3 23:01:09.304: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 71.664063ms I1003 23:01:11.376] Oct 3 23:01:11.376: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 2.143315635s I1003 23:01:13.448] Oct 3 23:01:13.448: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 4.215892214s I1003 23:01:15.521] Oct 3 23:01:15.521: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 6.288583492s I1003 23:01:17.594] Oct 3 23:01:17.593: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 8.360975368s I1003 23:01:19.665] Oct 3 23:01:19.665: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 10.432991439s I1003 23:01:21.738] Oct 3 23:01:21.738: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 12.505627014s I1003 23:01:23.811] Oct 3 23:01:23.811: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 14.57857709s I1003 23:01:25.883] Oct 3 23:01:25.883: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 16.650440557s I1003 23:01:27.955] Oct 3 23:01:27.955: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 18.722545025s I1003 23:01:30.027] Oct 3 23:01:30.027: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 20.794658192s I1003 23:01:32.105] Oct 3 23:01:32.105: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 22.872830306s I1003 23:01:34.177] Oct 3 23:01:34.177: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 24.94484677s I1003 23:01:36.250] Oct 3 23:01:36.249: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 27.016874434s I1003 23:01:38.322] Oct 3 23:01:38.321: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 29.089129698s I1003 23:01:40.394] Oct 3 23:01:40.394: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 31.161444362s I1003 23:01:42.466] Oct 3 23:01:42.466: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 33.233902125s I1003 23:01:44.539] Oct 3 23:01:44.539: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 35.30658419s I1003 23:01:46.611] Oct 3 23:01:46.611: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 37.37877035s I1003 23:01:48.684] Oct 3 23:01:48.683: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 39.451272011s I1003 23:01:50.756] Oct 3 23:01:50.756: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 41.523445069s I1003 23:01:52.828] Oct 3 23:01:52.828: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 43.595508725s I1003 23:01:54.899] Oct 3 23:01:54.899: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 45.666758774s I1003 23:01:56.971] Oct 3 23:01:56.971: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 47.738905329s I1003 23:01:59.044] Oct 3 23:01:59.043: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 49.811042882s I1003 23:02:01.115] Oct 3 23:02:01.115: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 51.882968934s I1003 23:02:03.188] Oct 3 23:02:03.188: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 53.95571949s I1003 23:02:05.261] Oct 3 23:02:05.260: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 56.028083343s I1003 23:02:07.333] Oct 3 23:02:07.332: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 58.100226493s I1003 23:02:09.408] Oct 3 23:02:09.408: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 1m0.175612968s I1003 23:02:11.483] Oct 3 23:02:11.483: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 1m2.250441637s I1003 23:02:13.555] Oct 3 23:02:13.555: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 1m4.322942788s I1003 23:02:15.627] Oct 3 23:02:15.627: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 1m6.394946433s I1003 23:02:17.700] Oct 3 23:02:17.699: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 1m8.467103379s I1003 23:02:19.772] Oct 3 23:02:19.772: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Pending", Reason="", readiness=false. Elapsed: 1m10.539345424s I1003 23:02:21.844] Oct 3 23:02:21.844: INFO: Pod "azuredisk-volume-tester-x585l": Phase="Failed", Reason="", readiness=false. Elapsed: 1m12.611898571s I1003 23:02:21.845] STEP: Saw pod failure I1003 23:02:21.845] Oct 3 23:02:21.844: INFO: Pod "azuredisk-volume-tester-x585l" satisfied condition "Error status code" I1003 23:02:21.845] STEP: checking that pod logs contain expected message I1003 23:02:21.922] Oct 3 23:02:21.922: INFO: deleting Pod "azuredisk-1268"/"azuredisk-volume-tester-x585l" I1003 23:02:21.998] Oct 3 23:02:21.997: INFO: Pod azuredisk-volume-tester-x585l has the following logs: /bin/sh: can't create /mnt/test-1/data: Read-only file system I1003 23:02:21.998] I1003 23:02:21.998] STEP: Deleting pod azuredisk-volume-tester-x585l in namespace azuredisk-1268 I1003 23:02:22.075] Oct 3 23:02:22.075: INFO: deleting PVC "azuredisk-1268"/"pvc-9tmsd" I1003 23:02:22.076] Oct 3 23:02:22.075: INFO: Deleting PersistentVolumeClaim "pvc-9tmsd" I1003 23:02:22.148] Oct 3 23:02:22.148: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-1268 to be removed I1003 23:02:22.224] Oct 3 23:02:22.224: INFO: Claim "azuredisk-1268" in namespace "pvc-9tmsd" doesn't exist in the system I1003 23:02:22.224] STEP: deleting PV "azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz" I1003 23:02:22.224] Oct 3 23:02:22.224: INFO: Deleting PersistentVolume "azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz" I1003 23:02:22.296] STEP: waiting for claim's PV "azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz" to be deleted I1003 23:02:22.296] Oct 3 23:02:22.296: INFO: Waiting up to 10m0s for PersistentVolume azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz to get deleted I1003 23:02:22.367] Oct 3 23:02:22.367: INFO: PersistentVolume azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz found and phase=Released (71.064657ms) I1003 23:02:27.440] Oct 3 23:02:27.439: INFO: PersistentVolume azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz found and phase=Released (5.143301615s) I1003 23:02:32.512] Oct 3 23:02:32.511: INFO: PersistentVolume azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz found and phase=Released (10.215418666s) I1003 23:02:37.583] Oct 3 23:02:37.583: INFO: PersistentVolume azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz found and phase=Released (15.286604105s) I1003 23:02:42.655] Oct 3 23:02:42.655: INFO: PersistentVolume azuredisk-1268-disk.csi.azure.com-preprovsioned-pv-ppgsz was removed I1003 23:02:42.655] [AfterEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:02:42.656] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:02:42.656] Oct 3 23:02:42.655: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:02:42.803] STEP: Destroying namespace "azuredisk-1268" for this suite. I1003 23:02:49.018] Oct 3 23:02:49.018: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 23:02:51.721] Oct 3 23:02:51.721: INFO: namespace azuredisk-1268 deletion completed in 8.918064962s I1003 23:02:51.722] [AfterEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:02:51.722] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:54 I1003 23:02:57.338] I1003 23:02:57.339] • [SLOW TEST:115.981 seconds] I1003 23:02:57.339] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:02:57.339] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:36 I1003 23:02:57.339] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1003 23:02:57.339] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:66 I1003 23:02:57.340] ------------------------------ I1003 23:02:57.340] Dynamic Provisioning I1003 23:02:57.340] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1003 23:02:57.340] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:115 I1003 23:02:57.340] [BeforeEach] Dynamic Provisioning I1003 23:02:57.341] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 23:02:57.341] STEP: Creating a kubernetes client I1003 23:02:57.341] Oct 3 23:02:57.338: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 23:02:57.341] STEP: Building a namespace api object, basename azuredisk I1003 23:02:57.555] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-9130 I1003 23:02:57.800] STEP: Waiting for a default service account to be provisioned in namespace I1003 23:02:57.870] [BeforeEach] Dynamic Provisioning I1003 23:02:57.871] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 23:02:57.871] [It] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1003 23:02:57.871] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:115 I1003 23:02:57.871] STEP: setting up the StorageClass I1003 23:02:57.872] STEP: creating a StorageClass I1003 23:02:57.942] STEP: setting up the PVC and PV I1003 23:02:57.942] STEP: creating a PVC I1003 23:02:58.017] STEP: waiting for PVC to be in phase "Bound" I1003 23:02:58.018] Oct 3 23:02:58.017: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-fmkjq] to have phase Bound I1003 23:02:58.088] Oct 3 23:02:58.088: INFO: PersistentVolumeClaim pvc-fmkjq found but phase is Pending instead of Bound. I1003 23:03:00.161] Oct 3 23:03:00.160: INFO: PersistentVolumeClaim pvc-fmkjq found and phase=Bound (2.143266985s) I1003 23:03:00.161] STEP: checking the PVC I1003 23:03:00.232] STEP: validating provisioned PV I1003 23:03:00.303] STEP: checking the PV I1003 23:03:00.303] STEP: deploying the pod I1003 23:03:00.375] STEP: checking that the pod is running I1003 23:04:12.519] STEP: setting up the StorageClass I1003 23:04:12.519] STEP: creating a StorageClass I1003 23:04:12.591] STEP: setting up the PVC and PV I1003 23:04:12.592] STEP: creating a PVC I1003 23:04:12.668] STEP: waiting for PVC to be in phase "Bound" I1003 23:04:12.669] Oct 3 23:04:12.668: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-zh4x8] to have phase Bound I1003 23:04:12.740] Oct 3 23:04:12.740: INFO: PersistentVolumeClaim pvc-zh4x8 found but phase is Pending instead of Bound. I1003 23:04:14.813] Oct 3 23:04:14.813: INFO: PersistentVolumeClaim pvc-zh4x8 found but phase is Pending instead of Bound. I1003 23:04:16.885] Oct 3 23:04:16.885: INFO: PersistentVolumeClaim pvc-zh4x8 found but phase is Pending instead of Bound. I1003 23:04:18.958] Oct 3 23:04:18.958: INFO: PersistentVolumeClaim pvc-zh4x8 found but phase is Pending instead of Bound. I1003 23:04:21.031] Oct 3 23:04:21.030: INFO: PersistentVolumeClaim pvc-zh4x8 found but phase is Pending instead of Bound. I1003 23:04:23.104] Oct 3 23:04:23.103: INFO: PersistentVolumeClaim pvc-zh4x8 found and phase=Bound (10.434932774s) I1003 23:04:23.104] STEP: checking the PVC I1003 23:04:23.176] STEP: validating provisioned PV I1003 23:04:23.248] STEP: checking the PV I1003 23:04:23.248] STEP: deploying the pod I1003 23:04:23.320] STEP: checking that the pod is running I1003 23:05:35.465] Oct 3 23:05:35.465: INFO: deleting Pod "azuredisk-9130"/"azuredisk-volume-tester-nz95b" I1003 23:05:35.542] Oct 3 23:05:35.542: INFO: Pod azuredisk-volume-tester-nz95b has the following logs: I1003 23:05:35.542] STEP: Deleting pod azuredisk-volume-tester-nz95b in namespace azuredisk-9130 I1003 23:05:35.616] Oct 3 23:05:35.615: INFO: deleting PVC "azuredisk-9130"/"pvc-zh4x8" I1003 23:05:35.616] Oct 3 23:05:35.615: INFO: Deleting PersistentVolumeClaim "pvc-zh4x8" I1003 23:05:35.689] STEP: waiting for claim's PV "pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07" to be deleted I1003 23:05:35.690] Oct 3 23:05:35.689: INFO: Waiting up to 10m0s for PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 to get deleted I1003 23:05:35.761] Oct 3 23:05:35.761: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (71.904462ms) I1003 23:05:40.834] Oct 3 23:05:40.834: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (5.144495054s) I1003 23:05:45.907] Oct 3 23:05:45.907: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (10.217477546s) I1003 23:05:50.979] Oct 3 23:05:50.979: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (15.290068431s) I1003 23:05:56.052] Oct 3 23:05:56.052: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (20.363137416s) I1003 23:06:01.125] Oct 3 23:06:01.124: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (25.43526999s) I1003 23:06:06.197] Oct 3 23:06:06.197: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Bound (30.507618963s) I1003 23:06:11.270] Oct 3 23:06:11.269: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (35.580293635s) I1003 23:06:16.342] Oct 3 23:06:16.342: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (40.652975403s) I1003 23:06:21.415] Oct 3 23:06:21.415: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (45.725561468s) I1003 23:06:26.494] Oct 3 23:06:26.494: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (50.804513178s) I1003 23:06:31.567] Oct 3 23:06:31.566: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (55.877443139s) I1003 23:06:36.639] Oct 3 23:06:36.639: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (1m0.949550689s) I1003 23:06:41.711] Oct 3 23:06:41.711: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (1m6.02213314s) I1003 23:06:46.784] Oct 3 23:06:46.784: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (1m11.094581387s) I1003 23:06:51.858] Oct 3 23:06:51.857: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (1m16.168343341s) I1003 23:06:56.930] Oct 3 23:06:56.930: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 found and phase=Released (1m21.241091884s) I1003 23:07:02.004] Oct 3 23:07:02.003: INFO: PersistentVolume pvc-529994d2-93de-42b3-9e21-3cb2bd78fd07 was removed I1003 23:07:02.004] Oct 3 23:07:02.003: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-9130 to be removed I1003 23:07:02.075] Oct 3 23:07:02.075: INFO: Claim "azuredisk-9130" in namespace "pvc-zh4x8" doesn't exist in the system I1003 23:07:02.076] Oct 3 23:07:02.075: INFO: deleting StorageClass azuredisk-9130-disk.csi.azure.com-dynamic-sc-jpcpf I1003 23:07:02.150] Oct 3 23:07:02.150: INFO: deleting Pod "azuredisk-9130"/"azuredisk-volume-tester-4lzqs" I1003 23:07:02.235] Oct 3 23:07:02.235: INFO: Pod azuredisk-volume-tester-4lzqs has the following logs: I1003 23:07:02.236] STEP: Deleting pod azuredisk-volume-tester-4lzqs in namespace azuredisk-9130 I1003 23:07:02.309] Oct 3 23:07:02.309: INFO: deleting PVC "azuredisk-9130"/"pvc-fmkjq" I1003 23:07:02.309] Oct 3 23:07:02.309: INFO: Deleting PersistentVolumeClaim "pvc-fmkjq" I1003 23:07:02.382] STEP: waiting for claim's PV "pvc-3659be62-afed-4d00-a3d7-615e02569e31" to be deleted I1003 23:07:02.383] Oct 3 23:07:02.382: INFO: Waiting up to 10m0s for PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 to get deleted I1003 23:07:02.454] Oct 3 23:07:02.454: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (71.343456ms) I1003 23:07:07.526] Oct 3 23:07:07.526: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (5.143284986s) I1003 23:07:12.598] Oct 3 23:07:12.598: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (10.215357414s) I1003 23:07:17.670] Oct 3 23:07:17.670: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (15.287876943s) I1003 23:07:22.743] Oct 3 23:07:22.743: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (20.360292568s) I1003 23:07:27.816] Oct 3 23:07:27.816: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (25.433304294s) I1003 23:07:32.889] Oct 3 23:07:32.888: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (30.506032816s) I1003 23:07:37.962] Oct 3 23:07:37.961: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (35.579133937s) I1003 23:07:43.034] Oct 3 23:07:43.034: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Bound (40.651746252s) I1003 23:07:48.107] Oct 3 23:07:48.107: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Released (45.724451364s) I1003 23:07:53.179] Oct 3 23:07:53.179: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Released (50.796747471s) I1003 23:07:58.253] Oct 3 23:07:58.252: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Released (55.870101483s) I1003 23:08:03.325] Oct 3 23:08:03.325: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 found and phase=Released (1m0.942533485s) I1003 23:08:08.397] Oct 3 23:08:08.397: INFO: PersistentVolume pvc-3659be62-afed-4d00-a3d7-615e02569e31 was removed I1003 23:08:08.397] Oct 3 23:08:08.397: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-9130 to be removed I1003 23:08:08.468] Oct 3 23:08:08.468: INFO: Claim "azuredisk-9130" in namespace "pvc-fmkjq" doesn't exist in the system I1003 23:08:08.468] Oct 3 23:08:08.468: INFO: deleting StorageClass azuredisk-9130-disk.csi.azure.com-dynamic-sc-t8d4m I1003 23:08:08.540] [AfterEach] Dynamic Provisioning I1003 23:08:08.541] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:08:08.541] Oct 3 23:08:08.540: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:08:08.681] STEP: Destroying namespace "azuredisk-9130" for this suite. I1003 23:08:14.898] Oct 3 23:08:14.898: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 23:08:17.600] Oct 3 23:08:17.600: INFO: namespace azuredisk-9130 deletion completed in 8.919017146s I1003 23:08:17.601] I1003 23:08:17.601] • [SLOW TEST:320.262 seconds] I1003 23:08:17.601] Dynamic Provisioning I1003 23:08:17.602] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1003 23:08:17.602] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1003 23:08:17.602] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:115 I1003 23:08:17.602] ------------------------------ I1003 23:08:17.602] Dynamic Provisioning I1003 23:08:17.603] should create a volume on demand and mount it as readOnly in a pod I1003 23:08:17.603] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:91 I1003 23:08:17.603] [BeforeEach] Dynamic Provisioning I1003 23:08:17.603] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 23:08:17.603] STEP: Creating a kubernetes client I1003 23:08:17.603] Oct 3 23:08:17.600: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 23:08:17.603] STEP: Building a namespace api object, basename azuredisk I1003 23:08:17.816] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-2283 I1003 23:08:18.059] STEP: Waiting for a default service account to be provisioned in namespace I1003 23:08:18.129] [BeforeEach] Dynamic Provisioning I1003 23:08:18.130] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 23:08:18.130] [It] should create a volume on demand and mount it as readOnly in a pod I1003 23:08:18.130] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:91 I1003 23:08:18.130] STEP: setting up the StorageClass I1003 23:08:18.130] STEP: creating a StorageClass I1003 23:08:18.206] STEP: setting up the PVC and PV I1003 23:08:18.206] STEP: creating a PVC I1003 23:08:18.285] STEP: waiting for PVC to be in phase "Bound" I1003 23:08:18.286] Oct 3 23:08:18.285: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-gsdlj] to have phase Bound I1003 23:08:18.357] Oct 3 23:08:18.357: INFO: PersistentVolumeClaim pvc-gsdlj found but phase is Pending instead of Bound. I1003 23:08:20.429] Oct 3 23:08:20.429: INFO: PersistentVolumeClaim pvc-gsdlj found but phase is Pending instead of Bound. I1003 23:08:22.500] Oct 3 23:08:22.500: INFO: PersistentVolumeClaim pvc-gsdlj found but phase is Pending instead of Bound. I1003 23:08:24.573] Oct 3 23:08:24.572: INFO: PersistentVolumeClaim pvc-gsdlj found but phase is Pending instead of Bound. I1003 23:08:26.645] Oct 3 23:08:26.645: INFO: PersistentVolumeClaim pvc-gsdlj found but phase is Pending instead of Bound. I1003 23:08:28.717] Oct 3 23:08:28.717: INFO: PersistentVolumeClaim pvc-gsdlj found and phase=Bound (10.43136621s) I1003 23:08:28.717] STEP: checking the PVC I1003 23:08:28.788] STEP: validating provisioned PV I1003 23:08:28.859] STEP: checking the PV I1003 23:08:28.860] STEP: deploying the pod I1003 23:08:28.932] STEP: checking that the pods command exits with an error I1003 23:08:28.932] Oct 3 23:08:28.932: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qs8q8" in namespace "azuredisk-2283" to be "Error status code" I1003 23:08:29.004] Oct 3 23:08:29.004: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 72.041861ms I1003 23:08:31.076] Oct 3 23:08:31.076: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.144237292s I1003 23:08:33.149] Oct 3 23:08:33.149: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.216793526s I1003 23:08:35.221] Oct 3 23:08:35.221: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.289136557s I1003 23:08:37.294] Oct 3 23:08:37.293: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.361362487s I1003 23:08:39.366] Oct 3 23:08:39.366: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.433619217s I1003 23:08:41.439] Oct 3 23:08:41.439: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 12.506641853s I1003 23:08:43.511] Oct 3 23:08:43.510: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 14.578263077s I1003 23:08:45.582] Oct 3 23:08:45.582: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 16.650105202s I1003 23:08:47.654] Oct 3 23:08:47.653: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 18.721320822s I1003 23:08:49.725] Oct 3 23:08:49.724: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 20.792578142s I1003 23:08:51.797] Oct 3 23:08:51.796: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 22.864522967s I1003 23:08:53.868] Oct 3 23:08:53.868: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 24.936061288s I1003 23:08:55.940] Oct 3 23:08:55.940: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 27.007803811s I1003 23:08:58.011] Oct 3 23:08:58.011: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 29.079027029s I1003 23:09:00.083] Oct 3 23:09:00.083: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 31.150888252s I1003 23:09:02.155] Oct 3 23:09:02.155: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 33.222752074s I1003 23:09:04.228] Oct 3 23:09:04.228: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 35.295766405s I1003 23:09:06.299] Oct 3 23:09:06.299: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 37.366694119s I1003 23:09:08.371] Oct 3 23:09:08.371: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 39.438834442s I1003 23:09:10.443] Oct 3 23:09:10.442: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 41.510459561s I1003 23:09:12.514] Oct 3 23:09:12.514: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 43.581800077s I1003 23:09:14.586] Oct 3 23:09:14.585: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 45.653446995s I1003 23:09:16.658] Oct 3 23:09:16.657: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 47.725600717s I1003 23:09:18.730] Oct 3 23:09:18.729: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 49.797299935s I1003 23:09:20.801] Oct 3 23:09:20.801: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 51.868824451s I1003 23:09:22.873] Oct 3 23:09:22.872: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 53.940427167s I1003 23:09:24.944] Oct 3 23:09:24.944: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 56.012032383s I1003 23:09:27.015] Oct 3 23:09:27.015: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 58.083177695s I1003 23:09:29.111] Oct 3 23:09:29.110: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m0.178554995s I1003 23:09:31.182] Oct 3 23:09:31.182: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m2.250123109s I1003 23:09:33.254] Oct 3 23:09:33.254: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m4.322122227s I1003 23:09:35.326] Oct 3 23:09:35.326: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m6.39367294s I1003 23:09:37.397] Oct 3 23:09:37.397: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m8.464947451s I1003 23:09:39.468] Oct 3 23:09:39.468: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m10.536117561s I1003 23:09:41.540] Oct 3 23:09:41.540: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Pending", Reason="", readiness=false. Elapsed: 1m12.607855075s I1003 23:09:43.612] Oct 3 23:09:43.611: INFO: Pod "azuredisk-volume-tester-qs8q8": Phase="Failed", Reason="", readiness=false. Elapsed: 1m14.679437987s I1003 23:09:43.612] STEP: Saw pod failure I1003 23:09:43.612] Oct 3 23:09:43.611: INFO: Pod "azuredisk-volume-tester-qs8q8" satisfied condition "Error status code" I1003 23:09:43.613] STEP: checking that pod logs contain expected message I1003 23:09:43.688] Oct 3 23:09:43.687: INFO: deleting Pod "azuredisk-2283"/"azuredisk-volume-tester-qs8q8" I1003 23:09:43.765] Oct 3 23:09:43.765: INFO: Pod azuredisk-volume-tester-qs8q8 has the following logs: touch: /mnt/test-1/data: Read-only file system I1003 23:09:43.765] I1003 23:09:43.766] STEP: Deleting pod azuredisk-volume-tester-qs8q8 in namespace azuredisk-2283 I1003 23:09:43.850] Oct 3 23:09:43.849: INFO: deleting PVC "azuredisk-2283"/"pvc-gsdlj" I1003 23:09:43.850] Oct 3 23:09:43.849: INFO: Deleting PersistentVolumeClaim "pvc-gsdlj" I1003 23:09:43.925] STEP: waiting for claim's PV "pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a" to be deleted I1003 23:09:43.925] Oct 3 23:09:43.925: INFO: Waiting up to 10m0s for PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a to get deleted I1003 23:09:43.995] Oct 3 23:09:43.995: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (70.037945ms) I1003 23:09:49.066] Oct 3 23:09:49.066: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (5.141379486s) I1003 23:09:54.138] Oct 3 23:09:54.137: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (10.212914327s) I1003 23:09:59.209] Oct 3 23:09:59.209: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (15.284309765s) I1003 23:10:04.281] Oct 3 23:10:04.280: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (20.355953803s) I1003 23:10:09.352] Oct 3 23:10:09.351: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (25.426954333s) I1003 23:10:14.423] Oct 3 23:10:14.423: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (30.498517766s) I1003 23:10:19.495] Oct 3 23:10:19.495: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (35.570093197s) I1003 23:10:24.566] Oct 3 23:10:24.566: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (40.64103852s) I1003 23:10:29.638] Oct 3 23:10:29.637: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a found and phase=Released (45.712861349s) I1003 23:10:34.709] Oct 3 23:10:34.708: INFO: PersistentVolume pvc-3d95d64f-caa4-4099-83bc-a9f6035a957a was removed I1003 23:10:34.709] Oct 3 23:10:34.708: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-2283 to be removed I1003 23:10:34.779] Oct 3 23:10:34.778: INFO: Claim "azuredisk-2283" in namespace "pvc-gsdlj" doesn't exist in the system I1003 23:10:34.779] Oct 3 23:10:34.778: INFO: deleting StorageClass azuredisk-2283-disk.csi.azure.com-dynamic-sc-w9d7s I1003 23:10:34.851] [AfterEach] Dynamic Provisioning I1003 23:10:34.852] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:10:34.852] Oct 3 23:10:34.851: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:10:34.994] STEP: Destroying namespace "azuredisk-2283" for this suite. I1003 23:10:41.208] Oct 3 23:10:41.208: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 23:10:43.876] Oct 3 23:10:43.876: INFO: namespace azuredisk-2283 deletion completed in 8.881803639s I1003 23:10:43.876] I1003 23:10:43.876] • [SLOW TEST:146.275 seconds] I1003 23:10:43.877] Dynamic Provisioning I1003 23:10:43.877] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1003 23:10:43.877] should create a volume on demand and mount it as readOnly in a pod I1003 23:10:43.877] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:91 I1003 23:10:43.878] ------------------------------ I1003 23:10:43.878] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:10:43.878] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1003 23:10:43.878] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:100 I1003 23:10:43.878] [BeforeEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:10:43.879] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 23:10:43.879] STEP: Creating a kubernetes client I1003 23:10:43.879] Oct 3 23:10:43.876: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 23:10:43.879] STEP: Building a namespace api object, basename azuredisk I1003 23:10:44.099] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-831 I1003 23:10:44.346] STEP: Waiting for a default service account to be provisioned in namespace I1003 23:10:44.416] [BeforeEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:10:44.416] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:48 I1003 23:10:44.416] [It] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1003 23:10:44.416] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:100 I1003 23:10:45.845] STEP: Successfully provisioned AzureDisk volume: "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-ca77b650-e62a-11e9-8665-024276f6d56b/providers/Microsoft.Compute/disks/pre-provisioned-retain-reclaimPolicy" I1003 23:10:45.845] I1003 23:10:45.846] STEP: setting up the PV I1003 23:10:45.846] STEP: creating a PV I1003 23:10:45.921] STEP: setting up the PVC I1003 23:10:45.922] STEP: creating a PVC I1003 23:10:45.995] STEP: waiting for PVC to be in phase "Bound" I1003 23:10:45.995] Oct 3 23:10:45.994: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-7zmxb] to have phase Bound I1003 23:10:46.065] Oct 3 23:10:46.065: INFO: PersistentVolumeClaim pvc-7zmxb found and phase=Bound (70.394247ms) I1003 23:10:46.065] STEP: checking the PVC I1003 23:10:46.137] STEP: validating provisioned PV I1003 23:10:46.208] STEP: checking the PV I1003 23:10:46.208] Oct 3 23:10:46.208: INFO: deleting PVC "azuredisk-831"/"pvc-7zmxb" I1003 23:10:46.209] Oct 3 23:10:46.208: INFO: Deleting PersistentVolumeClaim "pvc-7zmxb" I1003 23:10:46.280] Oct 3 23:10:46.280: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-831 to be removed I1003 23:10:46.351] Oct 3 23:10:46.351: INFO: Claim "azuredisk-831" in namespace "pvc-7zmxb" doesn't exist in the system I1003 23:10:46.352] Oct 3 23:10:46.351: INFO: Waiting up to 10m0s for PersistentVolume azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq to have phase Released I1003 23:10:46.422] Oct 3 23:10:46.422: INFO: PersistentVolume azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq found and phase=Released (70.81005ms) I1003 23:10:46.422] STEP: deleting PV "azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq" I1003 23:10:46.423] Oct 3 23:10:46.422: INFO: Deleting PersistentVolume "azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq" I1003 23:10:46.494] STEP: waiting for claim's PV "azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq" to be deleted I1003 23:10:46.494] Oct 3 23:10:46.494: INFO: Waiting up to 10m0s for PersistentVolume azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq to get deleted I1003 23:10:46.564] Oct 3 23:10:46.564: INFO: PersistentVolume azuredisk-831-disk.csi.azure.com-preprovsioned-pv-bzjsq was removed I1003 23:10:46.565] [AfterEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:10:46.565] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:10:46.565] Oct 3 23:10:46.564: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:10:46.703] STEP: Destroying namespace "azuredisk-831" for this suite. I1003 23:10:52.923] Oct 3 23:10:52.923: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 23:10:55.615] Oct 3 23:10:55.615: INFO: namespace azuredisk-831 deletion completed in 8.912401868s I1003 23:10:55.616] [AfterEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:10:55.616] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:54 I1003 23:11:01.131] I1003 23:11:01.132] • [SLOW TEST:17.255 seconds] I1003 23:11:01.132] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1003 23:11:01.132] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:36 I1003 23:11:01.132] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1003 23:11:01.133] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/pre_provisioning.go:100 I1003 23:11:01.133] ------------------------------ I1003 23:11:01.133] Dynamic Provisioning I1003 23:11:01.133] [env] should retain PV with reclaimPolicy "Retain" I1003 23:11:01.133] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:193 I1003 23:11:01.133] [BeforeEach] Dynamic Provisioning I1003 23:11:01.134] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 23:11:01.134] STEP: Creating a kubernetes client I1003 23:11:01.134] Oct 3 23:11:01.131: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 23:11:01.134] STEP: Building a namespace api object, basename azuredisk I1003 23:11:01.345] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-8347 I1003 23:11:01.586] STEP: Waiting for a default service account to be provisioned in namespace I1003 23:11:01.655] [BeforeEach] Dynamic Provisioning I1003 23:11:01.656] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 23:11:01.656] [It] [env] should retain PV with reclaimPolicy "Retain" I1003 23:11:01.656] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:193 I1003 23:11:01.656] STEP: setting up the StorageClass I1003 23:11:01.656] STEP: creating a StorageClass I1003 23:11:01.726] STEP: setting up the PVC and PV I1003 23:11:01.727] STEP: creating a PVC I1003 23:11:01.799] STEP: waiting for PVC to be in phase "Bound" I1003 23:11:01.800] Oct 3 23:11:01.799: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-dh79n] to have phase Bound I1003 23:11:01.870] Oct 3 23:11:01.869: INFO: PersistentVolumeClaim pvc-dh79n found but phase is Pending instead of Bound. I1003 23:11:03.941] Oct 3 23:11:03.941: INFO: PersistentVolumeClaim pvc-dh79n found but phase is Pending instead of Bound. I1003 23:11:06.014] Oct 3 23:11:06.014: INFO: PersistentVolumeClaim pvc-dh79n found but phase is Pending instead of Bound. I1003 23:11:08.087] Oct 3 23:11:08.086: INFO: PersistentVolumeClaim pvc-dh79n found but phase is Pending instead of Bound. I1003 23:11:10.158] Oct 3 23:11:10.158: INFO: PersistentVolumeClaim pvc-dh79n found but phase is Pending instead of Bound. I1003 23:11:12.229] Oct 3 23:11:12.228: INFO: PersistentVolumeClaim pvc-dh79n found and phase=Bound (10.429196445s) I1003 23:11:12.229] STEP: checking the PVC I1003 23:11:12.299] STEP: validating provisioned PV I1003 23:11:12.369] STEP: checking the PV I1003 23:11:12.370] Oct 3 23:11:12.369: INFO: deleting PVC "azuredisk-8347"/"pvc-dh79n" I1003 23:11:12.370] Oct 3 23:11:12.369: INFO: Deleting PersistentVolumeClaim "pvc-dh79n" I1003 23:11:12.443] Oct 3 23:11:12.442: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-8347 to be removed I1003 23:11:12.515] Oct 3 23:11:12.514: INFO: Claim "azuredisk-8347" in namespace "pvc-dh79n" doesn't exist in the system I1003 23:11:12.515] Oct 3 23:11:12.514: INFO: Waiting up to 10m0s for PersistentVolume pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e to have phase Released I1003 23:11:12.585] Oct 3 23:11:12.585: INFO: PersistentVolume pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e found and phase=Released (70.513748ms) I1003 23:11:12.586] STEP: deleting PV "pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e" I1003 23:11:12.586] Oct 3 23:11:12.585: INFO: Deleting PersistentVolume "pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e" I1003 23:11:12.659] STEP: waiting for claim's PV "pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e" to be deleted I1003 23:11:12.659] Oct 3 23:11:12.659: INFO: Waiting up to 10m0s for PersistentVolume pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e to get deleted I1003 23:11:12.730] Oct 3 23:11:12.729: INFO: PersistentVolume pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e was removed I1003 23:11:12.730] STEP: deleting azuredisk volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-ca77b650-e62a-11e9-8665-024276f6d56b/providers/Microsoft.Compute/disks/pvc-2d866f68-8e22-41b8-a77f-c1d16ae19d4e" I1003 23:11:13.350] [AfterEach] Dynamic Provisioning I1003 23:11:13.350] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:11:13.351] Oct 3 23:11:13.350: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:11:13.421] STEP: Destroying namespace "azuredisk-8347" for this suite. I1003 23:11:19.635] Oct 3 23:11:19.635: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1003 23:11:22.305] Oct 3 23:11:22.305: INFO: namespace azuredisk-8347 deletion completed in 8.883872629s I1003 23:11:22.306] I1003 23:11:22.306] • [SLOW TEST:21.174 seconds] I1003 23:11:22.306] Dynamic Provisioning I1003 23:11:22.306] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1003 23:11:22.307] [env] should retain PV with reclaimPolicy "Retain" I1003 23:11:22.307] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:193 I1003 23:11:22.307] ------------------------------ I1003 23:11:22.307] Dynamic Provisioning I1003 23:11:22.308] should create a deployment object, write and read to it, delete the pod and write and read to it again I1003 23:11:22.308] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:152 I1003 23:11:22.308] [BeforeEach] Dynamic Provisioning I1003 23:11:22.309] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:150 I1003 23:11:22.309] STEP: Creating a kubernetes client I1003 23:11:22.309] Oct 3 23:11:22.305: INFO: >>> kubeConfig: /workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json I1003 23:11:22.309] STEP: Building a namespace api object, basename azuredisk I1003 23:11:22.519] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azuredisk-684 I1003 23:11:22.761] STEP: Waiting for a default service account to be provisioned in namespace I1003 23:11:22.832] [BeforeEach] Dynamic Provisioning I1003 23:11:22.832] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:39 I1003 23:11:22.832] [It] should create a deployment object, write and read to it, delete the pod and write and read to it again I1003 23:11:22.832] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:152 I1003 23:11:22.833] STEP: setting up the StorageClass I1003 23:11:22.833] STEP: creating a StorageClass I1003 23:11:22.903] STEP: setting up the PVC I1003 23:11:22.903] STEP: creating a PVC I1003 23:11:22.977] STEP: waiting for PVC to be in phase "Bound" I1003 23:11:22.977] Oct 3 23:11:22.977: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-bv5c6] to have phase Bound I1003 23:11:23.047] Oct 3 23:11:23.047: INFO: PersistentVolumeClaim pvc-bv5c6 found but phase is Pending instead of Bound. I1003 23:11:25.119] Oct 3 23:11:25.118: INFO: PersistentVolumeClaim pvc-bv5c6 found but phase is Pending instead of Bound. I1003 23:11:27.190] Oct 3 23:11:27.189: INFO: PersistentVolumeClaim pvc-bv5c6 found but phase is Pending instead of Bound. I1003 23:11:29.262] Oct 3 23:11:29.261: INFO: PersistentVolumeClaim pvc-bv5c6 found but phase is Pending instead of Bound. I1003 23:11:31.333] Oct 3 23:11:31.333: INFO: PersistentVolumeClaim pvc-bv5c6 found but phase is Pending instead of Bound. I1003 23:11:33.405] Oct 3 23:11:33.405: INFO: PersistentVolumeClaim pvc-bv5c6 found and phase=Bound (10.42805082s) I1003 23:11:33.405] STEP: checking the PVC I1003 23:11:33.475] STEP: validating provisioned PV I1003 23:11:33.547] STEP: checking the PV I1003 23:11:33.547] STEP: setting up the Deployment I1003 23:11:33.547] STEP: deploying the deployment I1003 23:11:33.692] Oct 3 23:11:33.691: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:35.764] Oct 3 23:11:35.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:37.764] Oct 3 23:11:37.764: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:39.764] Oct 3 23:11:39.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:41.764] Oct 3 23:11:41.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:43.764] Oct 3 23:11:43.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:45.764] Oct 3 23:11:45.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:47.764] Oct 3 23:11:47.764: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:49.764] Oct 3 23:11:49.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:51.763] Oct 3 23:11:51.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:53.764] Oct 3 23:11:53.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:55.764] Oct 3 23:11:55.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:57.764] Oct 3 23:11:57.764: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:11:59.764] Oct 3 23:11:59.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:01.763] Oct 3 23:12:01.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:03.764] Oct 3 23:12:03.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:05.765] Oct 3 23:12:05.764: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:07.763] Oct 3 23:12:07.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:09.764] Oct 3 23:12:09.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:11.763] Oct 3 23:12:11.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:13.763] Oct 3 23:12:13.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:15.763] Oct 3 23:12:15.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:17.764] Oct 3 23:12:17.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:19.762] Oct 3 23:12:19.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:21.763] Oct 3 23:12:21.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:23.764] Oct 3 23:12:23.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:25.763] Oct 3 23:12:25.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:27.764] Oct 3 23:12:27.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:29.763] Oct 3 23:12:29.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:31.764] Oct 3 23:12:31.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:33.763] Oct 3 23:12:33.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:35.763] Oct 3 23:12:35.762: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:37.764] Oct 3 23:12:37.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:39.770] Oct 3 23:12:39.769: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:41.764] Oct 3 23:12:41.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:43.763] Oct 3 23:12:43.763: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63705741093, loc:(*time.Location)(0x3588fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-xdjdg-56988d74fd\" is progressing."}}, CollisionCount:(*int32)(nil)} I1003 23:12:45.908] STEP: checking that the pod is running I1003 23:12:46.052] STEP: deleting the pod for deployment I1003 23:12:46.052] Oct 3 23:12:46.052: INFO: Deleting pod "azuredisk-volume-tester-xdjdg-56988d74fd-ccphq" in namespace "azuredisk-684" I1003 23:12:46.127] Oct 3 23:12:46.126: INFO: Waiting for pod "azuredisk-volume-tester-xdjdg-56988d74fd-ccphq" in namespace "azuredisk-684" to be fully deleted I1003 23:13:22.270] STEP: checking again that the pod is running I1003 23:15:08.559] STEP: checking pod exec I1003 23:15:08.559] Oct 3 23:15:08.559: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/workspace/aks070243480/kubeconfig/kubeconfig.eastus2.json exec azuredisk-volume-tester-xdjdg-56988d74fd-m8f45 --namespace=azuredisk-684 -- cat /mnt/test-1/data' I1003 23:15:10.721] Oct 3 23:15:10.721: INFO: stderr: "" I1003 23:15:10.722] Oct 3 23:15:10.721: INFO: stdout: "hello world\nhello world\n" I1003 23:15:10.722] Oct 3 23:15:10.721: INFO: deleting Deployment "azuredisk-684"/"azuredisk-volume-tester-xdjdg" I1003 23:15:10.799] Oct 3 23:15:10.799: INFO: Pod azuredisk-volume-tester-xdjdg-56988d74fd-m8f45 has the following logs: I1003 23:15:10.874] Oct 3 23:15:10.873: INFO: deleting PVC "azuredisk-684"/"pvc-bv5c6" I1003 23:15:10.874] Oct 3 23:15:10.873: INFO: Deleting PersistentVolumeClaim "pvc-bv5c6" I1003 23:15:10.947] STEP: waiting for claim's PV "pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534" to be deleted I1003 23:15:10.947] Oct 3 23:15:10.946: INFO: Waiting up to 10m0s for PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 to get deleted I1003 23:15:11.018] Oct 3 23:15:11.018: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (71.269553ms) I1003 23:15:16.091] Oct 3 23:15:16.091: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (5.144472903s) I1003 23:15:21.163] Oct 3 23:15:21.163: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (10.21617294s) I1003 23:15:26.236] Oct 3 23:15:26.236: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (15.289510289s) I1003 23:15:31.309] Oct 3 23:15:31.308: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (20.36203903s) I1003 23:15:36.381] Oct 3 23:15:36.380: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (25.433975365s) I1003 23:15:41.453] Oct 3 23:15:41.453: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (30.506283203s) I1003 23:15:46.525] Oct 3 23:15:46.524: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (35.577891933s) I1003 23:15:51.596] Oct 3 23:15:51.596: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Bound (40.649683764s) I1003 23:15:56.667] Oct 3 23:15:56.667: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Released (45.720596287s) I1003 23:16:01.739] Oct 3 23:16:01.739: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Released (50.792305816s) I1003 23:16:06.810] Oct 3 23:16:06.810: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Released (55.863833341s) I1003 23:16:11.881] Oct 3 23:16:11.881: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 found and phase=Released (1m0.93459376s) I1003 23:16:16.952] Oct 3 23:16:16.952: INFO: PersistentVolume pvc-9fa0c169-3061-43c4-aa0e-6083f3ca3534 was removed I1003 23:16:16.953] Oct 3 23:16:16.952: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-684 to be removed I1003 23:16:17.026] Oct 3 23:16:17.025: INFO: Claim "azuredisk-684" in namespace "pvc-bv5c6" doesn't exist in the system I1003 23:16:17.026] Oct 3 23:16:17.025: INFO: deleting StorageClass azuredisk-684-disk.csi.azure.com-dynamic-sc-2n7hv I1003 23:16:17.099] [AfterEach] Dynamic Provisioning I1003 23:16:17.099] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1003 23:16:17.099] Oct 3 23:16:17.098: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1003 23:16:17.237] STEP: Destroying namespace "azuredisk-684" for this suite. I1003 23:16:18.132] panic: test timed out after 30m0s I1003 23:16:18.133] I1003 23:16:18.133] goroutine 2219 [running]: I1003 23:16:18.133] testing.(*M).startAlarm.func1() I1003 23:16:18.133] /usr/local/go/src/testing/testing.go:1334 +0xdf I1003 23:16:18.133] created by time.goFunc I1003 23:16:18.134] /usr/local/go/src/time/sleep.go:169 +0x44 I1003 23:16:18.134] I1003 23:16:18.134] goroutine 1 [chan receive, 30 minutes]: I1003 23:16:18.134] testing.(*T).Run(0xc000305300, 0x1d57539, 0x7, 0x1e2c410, 0x482da6) I1003 23:16:18.134] /usr/local/go/src/testing/testing.go:917 +0x381 I1003 23:16:18.135] testing.runTests.func1(0xc000305200) I1003 23:16:18.135] /usr/local/go/src/testing/testing.go:1157 +0x78 I1003 23:16:18.135] testing.tRunner(0xc000305200, 0xc0007dde30) I1003 23:16:18.135] /usr/local/go/src/testing/testing.go:865 +0xc0 I1003 23:16:18.135] testing.runTests(0xc0007c52e0, 0x3554890, 0x1, 0x1, 0x358b098) I1003 23:16:18.135] /usr/local/go/src/testing/testing.go:1155 +0x2a9 I1003 23:16:18.135] testing.(*M).Run(0xc000837f80, 0x0) I1003 23:16:18.136] /usr/local/go/src/testing/testing.go:1072 +0x162 I1003 23:16:18.136] main.main() I1003 23:16:18.136] _testmain.go:42 +0x13e I1003 23:16:18.136] I1003 23:16:18.136] goroutine 19 [chan receive]: I1003 23:16:18.136] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/klog.(*loggingT).flushDaemon(0x35895e0) I1003 23:16:18.137] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/klog/klog.go:1018 +0x8b I1003 23:16:18.137] created by github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/klog.init.0 I1003 23:16:18.137] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/klog/klog.go:404 +0x6c I1003 23:16:18.137] I1003 23:16:18.137] goroutine 21 [select]: I1003 23:16:18.137] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/go.opencensus.io/stats/view.(*worker).start(0xc0000d3340) I1003 23:16:18.138] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/go.opencensus.io/stats/view/worker.go:152 +0xdd I1003 23:16:18.138] created by github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/go.opencensus.io/stats/view.init.0 I1003 23:16:18.138] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/go.opencensus.io/stats/view/worker.go:29 +0x57 I1003 23:16:18.138] I1003 23:16:18.138] goroutine 39 [syscall, 30 minutes]: I1003 23:16:18.138] os/signal.signal_recv(0x45f076) I1003 23:16:18.139] /usr/local/go/src/runtime/sigqueue.go:139 +0x9c I1003 23:16:18.139] os/signal.loop() I1003 23:16:18.139] /usr/local/go/src/os/signal/signal_unix.go:23 +0x22 I1003 23:16:18.139] created by os/signal.init.0 I1003 23:16:18.140] /usr/local/go/src/os/signal/signal_unix.go:29 +0x41 I1003 23:16:18.140] I1003 23:16:18.140] goroutine 30 [select]: I1003 23:16:18.140] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait.WaitFor(0xc0006e0ba0, 0xc000658750, 0xc0007b2420, 0x0, 0x0) I1003 23:16:18.140] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:424 +0x110 I1003 23:16:18.140] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait.pollInternal(0xc0006e0ba0, 0xc000658750, 0x0, 0x0) I1003 23:16:18.141] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:312 +0x8a I1003 23:16:18.141] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait.pollImmediateInternal(0xc0006e0ba0, 0xc000658750, 0xc0006e0ba0, 0xc000658750) I1003 23:16:18.141] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:337 +0x70 I1003 23:16:18.141] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait.PollImmediate(0x77359400, 0x8bb2c97000, 0xc000658750, 0x0, 0x0) I1003 23:16:18.141] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:326 +0x4d I1003 23:16:18.142] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework.deleteNS(0x20e1980, 0xc000ec6500, 0x203cce0, 0xc0000cf028, 0xc000640080, 0xd, 0x8bb2c97000, 0x4, 0x0) I1003 23:16:18.142] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/util.go:1100 +0x160 I1003 23:16:18.142] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework.(*Framework).AfterEach.func1(0xc0001b3cc0) I1003 23:16:18.142] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:308 +0x21c I1003 23:16:18.142] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework.(*Framework).AfterEach(0xc0001b3cc0) I1003 23:16:18.143] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:394 +0x40e I1003 23:16:18.143] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc0002fb740, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...) I1003 23:16:18.143] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/leafnodes/runner.go:113 +0x9c I1003 23:16:18.143] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).run(0xc0002fb740, 0x98, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...) I1003 23:16:18.143] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/leafnodes/runner.go:64 +0xcf I1003 23:16:18.144] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*SetupNode).Run(0xc0000cf250, 0x203c100, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...) I1003 23:16:18.144] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/leafnodes/setup_nodes.go:15 +0x64 I1003 23:16:18.144] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/spec.(*Spec).runSample.func1(0xc000def8d0, 0xc000720690, 0x203c100, 0xc0000d36c0) I1003 23:16:18.144] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/spec/spec.go:180 +0x347 I1003 23:16:18.144] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/spec.(*Spec).runSample(0xc000720690, 0x0, 0x203c100, 0xc0000d36c0) I1003 23:16:18.145] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/spec/spec.go:218 +0x5fe I1003 23:16:18.145] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/spec.(*Spec).Run(0xc000720690, 0x203c100, 0xc0000d36c0) I1003 23:16:18.145] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/spec/spec.go:138 +0xf4 I1003 23:16:18.145] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpec(0xc00050e140, 0xc000720690, 0x8) I1003 23:16:18.145] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:200 +0x10f I1003 23:16:18.146] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpecs(0xc00050e140, 0x1) I1003 23:16:18.146] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:170 +0x124 I1003 23:16:18.146] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).Run(0xc00050e140, 0xc00004cc98) I1003 23:16:18.146] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:66 +0x117 I1003 23:16:18.146] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/suite.(*Suite).Run(0xc000579b80, 0x7f23715ae320, 0xc000305300, 0x1d8a83c, 0x25, 0xc0006f8d70, 0x1, 0x1, 0x2092600, 0xc0000d36c0, ...) I1003 23:16:18.147] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/suite/suite.go:62 +0x42e I1003 23:16:18.147] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo.RunSpecsWithCustomReporters(0x203dac0, 0xc000305300, 0x1d8a83c, 0x25, 0xc0004fff50, 0x1, 0x1, 0x1b6b680) I1003 23:16:18.147] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/ginkgo_dsl.go:221 +0x217 I1003 23:16:18.147] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo.RunSpecs(0x203dac0, 0xc000305300, 0x1d8a83c, 0x25, 0x2f4ba6a96563f1) I1003 23:16:18.148] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/ginkgo_dsl.go:202 +0x89 I1003 23:16:18.148] github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e.TestE2E(0xc000305300) I1003 23:16:18.148] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/suite_test.go:131 +0xa4 I1003 23:16:18.148] testing.tRunner(0xc000305300, 0x1e2c410) I1003 23:16:18.148] /usr/local/go/src/testing/testing.go:865 +0xc0 I1003 23:16:18.149] created by testing.(*T).Run I1003 23:16:18.149] /usr/local/go/src/testing/testing.go:916 +0x35a I1003 23:16:18.149] I1003 23:16:18.149] goroutine 31 [chan receive, 30 minutes]: I1003 23:16:18.149] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).registerForInterrupts(0xc00050e140, 0xc0000b5440) I1003 23:16:18.150] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:223 +0xd1 I1003 23:16:18.150] created by github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).Run I1003 23:16:18.150] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:60 +0x86 I1003 23:16:18.150] I1003 23:16:18.150] goroutine 100 [semacquire, 27 minutes]: I1003 23:16:18.150] sync.runtime_Semacquire(0xc00069a648) I1003 23:16:18.151] /usr/local/go/src/runtime/sema.go:56 +0x39 I1003 23:16:18.151] sync.(*WaitGroup).Wait(0xc00069a640) I1003 23:16:18.151] /usr/local/go/src/sync/waitgroup.go:130 +0x65 I1003 23:16:18.151] github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/csi-common.(*nonBlockingGRPCServer).Wait(0xc00069a640) I1003 23:16:18.151] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/csi-common/server.go:58 +0x2d I1003 23:16:18.152] github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.(*Driver).Run(0xc0005990e0, 0xc0006d60c0, 0x39) I1003 23:16:18.152] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk/azuredisk.go:133 +0x371 I1003 23:16:18.152] github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e.glob..func3.2() I1003 23:16:18.152] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/suite_test.go:100 +0x118 I1003 23:16:18.152] created by github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e.glob..func3 I1003 23:16:18.153] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/suite_test.go:98 +0xb25 I1003 23:16:18.153] I1003 23:16:18.153] goroutine 117 [IO wait, 27 minutes]: I1003 23:16:18.153] internal/poll.runtime_pollWait(0x7f23715af1e0, 0x72, 0x0) I1003 23:16:18.153] /usr/local/go/src/runtime/netpoll.go:182 +0x56 I1003 23:16:18.154] internal/poll.(*pollDesc).wait(0xc00070f698, 0x72, 0x0, 0x0, 0x1d576ac) I1003 23:16:18.154] /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b I1003 23:16:18.154] internal/poll.(*pollDesc).waitRead(...) I1003 23:16:18.154] /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 I1003 23:16:18.154] internal/poll.(*FD).Accept(0xc00070f680, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) I1003 23:16:18.155] /usr/local/go/src/internal/poll/fd_unix.go:384 +0x1ba I1003 23:16:18.155] net.(*netFD).accept(0xc00070f680, 0xc0005c46e0, 0xd100000000000000, 0x0) I1003 23:16:18.155] /usr/local/go/src/net/fd_unix.go:238 +0x42 I1003 23:16:18.155] net.(*UnixListener).accept(0xc0006d3380, 0x42e54f, 0xc00003dff0, 0xc000089d48) I1003 23:16:18.155] /usr/local/go/src/net/unixsock_posix.go:162 +0x32 I1003 23:16:18.155] net.(*UnixListener).Accept(0xc0006d3380, 0x1e2e4a0, 0xc0004c29a0, 0xc00069a720, 0xc00070b520) I1003 23:16:18.155] /usr/local/go/src/net/unixsock.go:260 +0x48 I1003 23:16:18.155] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/google.golang.org/grpc.(*Server).Serve(0xc0004c29a0, 0x207c300, 0xc0006d3380, 0x0, 0x0) I1003 23:16:18.156] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/google.golang.org/grpc/server.go:586 +0x1f2 I1003 23:16:18.156] github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/csi-common.(*nonBlockingGRPCServer).serve(0xc00069a640, 0xc0006d60c0, 0x39, 0x2069080, 0xc0005990e0, 0x20c3c80, 0xc0005990e0, 0x20ad640, 0xc0005990e0) I1003 23:16:18.156] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/csi-common/server.go:104 +0x370 I1003 23:16:18.156] created by github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/csi-common.(*nonBlockingGRPCServer).Start I1003 23:16:18.156] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/csi-common/server.go:54 +0xbe I1003 23:16:18.156] I1003 23:16:18.156] goroutine 122 [IO wait]: I1003 23:16:18.157] internal/poll.runtime_pollWait(0x7f23715af110, 0x72, 0xffffffffffffffff) I1003 23:16:18.157] /usr/local/go/src/runtime/netpoll.go:182 +0x56 I1003 23:16:18.157] internal/poll.(*pollDesc).wait(0xc00081d918, 0x72, 0xf400, 0xf400, 0xffffffffffffffff) I1003 23:16:18.157] /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b I1003 23:16:18.158] internal/poll.(*pollDesc).waitRead(...) I1003 23:16:18.158] /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 I1003 23:16:18.158] internal/poll.(*FD).Read(0xc00081d900, 0xc000b94000, 0xf400, 0xf400, 0x0, 0x0, 0x0) I1003 23:16:18.158] /usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b I1003 23:16:18.158] net.(*netFD).Read(0xc00081d900, 0xc000b94000, 0xf400, 0xf400, 0x203000, 0x0, 0xf3bc) I1003 23:16:18.158] /usr/local/go/src/net/fd_unix.go:202 +0x4f I1003 23:16:18.158] net.(*conn).Read(0xc0004b6360, 0xc000b94000, 0xf400, 0xf400, 0x0, 0x0, 0x0) I1003 23:16:18.159] /usr/local/go/src/net/net.go:177 +0x69 I1003 23:16:18.159] crypto/tls.(*atLeastReader).Read(0xc00077c1c0, 0xc000b94000, 0xf400, 0xf400, 0xc000082a08, 0x446372, 0xc0000829e0) I1003 23:16:18.159] /usr/local/go/src/crypto/tls/conn.go:761 +0x60 I1003 23:16:18.159] bytes.(*Buffer).ReadFrom(0xc0002e0958, 0x203adc0, 0xc00077c1c0, 0x40bb55, 0x1b09040, 0x1cd51a0) I1003 23:16:18.159] /usr/local/go/src/bytes/buffer.go:207 +0xbd I1003 23:16:18.159] crypto/tls.(*Conn).readFromUntil(0xc0002e0700, 0x203d540, 0xc0004b6360, 0x5, 0xc0004b6360, 0x10b) I1003 23:16:18.159] /usr/local/go/src/crypto/tls/conn.go:783 +0xf8 I1003 23:16:18.160] crypto/tls.(*Conn).readRecordOrCCS(0xc0002e0700, 0x1e30e00, 0xc0002e0838, 0xc000082d58) I1003 23:16:18.160] /usr/local/go/src/crypto/tls/conn.go:590 +0x125 I1003 23:16:18.160] crypto/tls.(*Conn).readRecord(...) I1003 23:16:18.160] /usr/local/go/src/crypto/tls/conn.go:558 I1003 23:16:18.160] crypto/tls.(*Conn).Read(0xc0002e0700, 0xc000954000, 0x1000, 0x1000, 0x0, 0x0, 0x0) I1003 23:16:18.160] /usr/local/go/src/crypto/tls/conn.go:1236 +0x137 I1003 23:16:18.160] bufio.(*Reader).Read(0xc00009d380, 0xc0007ae498, 0x9, 0x9, 0x408014, 0xc000eb0060, 0xc000082d58) I1003 23:16:18.160] /usr/local/go/src/bufio/bufio.go:223 +0x23e I1003 23:16:18.161] io.ReadAtLeast(0x203ac00, 0xc00009d380, 0xc0007ae498, 0x9, 0x9, 0x9, 0x203afe0, 0xc00038dbb0, 0xc0000be030) I1003 23:16:18.161] /usr/local/go/src/io/io.go:310 +0x88 I1003 23:16:18.161] io.ReadFull(...) I1003 23:16:18.161] /usr/local/go/src/io/io.go:329 I1003 23:16:18.161] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.readFrameHeader(0xc0007ae498, 0x9, 0x9, 0x203ac00, 0xc00009d380, 0x0, 0x0, 0x0, 0x0) I1003 23:16:18.161] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/frame.go:237 +0x88 I1003 23:16:18.161] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*Framer).ReadFrame(0xc0007ae460, 0xc000658bd0, 0x0, 0x0, 0x0) I1003 23:16:18.162] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/frame.go:492 +0xa1 I1003 23:16:18.162] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*clientConnReadLoop).run(0xc000082fb8, 0x1e2e300, 0xc0004fafb8) I1003 23:16:18.162] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/transport.go:1686 +0x8d I1003 23:16:18.162] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*ClientConn).readLoop(0xc00054fe00) I1003 23:16:18.162] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/transport.go:1614 +0x76 I1003 23:16:18.162] created by github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*Transport).newClientConn I1003 23:16:18.163] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/transport.go:673 +0x637 I1003 23:16:18.163] I1003 23:16:18.163] goroutine 2218 [select]: I1003 23:16:18.163] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait.poller.func1.1(0xc0007b24e0, 0x77359400, 0x8bb2c97000, 0xc0007b2480) I1003 23:16:18.163] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:473 +0x153 I1003 23:16:18.163] created by github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait.poller.func1 I1003 23:16:18.163] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:456 +0x8c I1003 23:16:18.164] FAIL github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e 1800.054s I1003 23:16:18.319] Makefile:59: recipe for target 'e2e-test' failed W1003 23:16:18.419] make: *** [e2e-test] Error 1 W1003 23:16:18.419] 2019/10/03 23:16:18 process.go:155: Step 'make e2e-test' finished in 30m50.89614331s W1003 23:16:18.420] 2019/10/03 23:16:18 azure.go:901: Deleting resource group: kubetest-ca77b650-e62a-11e9-8665-024276f6d56b. W1003 23:26:12.624] 2019/10/03 23:26:12 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W1003 23:26:12.624] 2019/10/03 23:26:12 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W1003 23:26:13.396] 2019/10/03 23:26:13 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 772.347578ms W1003 23:26:13.397] 2019/10/03 23:26:13 main.go:319: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] W1003 23:26:13.400] Traceback (most recent call last): W1003 23:26:13.400] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in W1003 23:26:13.401] main(parse_args()) W1003 23:26:13.401] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W1003 23:26:13.401] mode.start(runner_args) W1003 23:26:13.402] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W1003 23:26:13.402] check_env(env, self.command, *args) W1003 23:26:13.402] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W1003 23:26:13.402] subprocess.check_call(cmd, env=env) W1003 23:26:13.402] File "/usr/lib/python2.7/subprocess.py", line 186, in check_call W1003 23:26:13.403] raise CalledProcessError(retcode, cmd) W1003 23:26:13.403] 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-disk-csi-driver=True')' returned non-zero exit status 1 E1003 23:26:13.408] Command failed I1003 23:26:13.409] process 690 exited with code 1 after 74.4m E1003 23:26:13.409] FAIL: pull-azuredisk-csi-driver-e2e I1003 23:26:13.409] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1003 23:26:21.513] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1003 23:26:21.561] process 27771 exited with code 0 after 0.1m I1003 23:26:21.561] Call: gcloud config get-value account I1003 23:26:22.419] process 27783 exited with code 0 after 0.0m I1003 23:26:22.420] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1003 23:26:22.420] Upload result and artifacts... I1003 23:26:22.420] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779 I1003 23:26:22.421] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779/artifacts W1003 23:26:23.929] CommandException: One or more URLs matched no objects. E1003 23:26:24.005] Command failed I1003 23:26:24.006] process 27795 exited with code 1 after 0.0m W1003 23:26:24.006] Remote dir gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779/artifacts not exist yet I1003 23:26:24.006] 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_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779/artifacts I1003 23:26:25.541] process 27937 exited with code 0 after 0.0m I1003 23:26:25.541] Call: git rev-parse HEAD I1003 23:26:25.544] process 28464 exited with code 0 after 0.0m I1003 23:26:25.544] Call: git rev-parse HEAD I1003 23:26:25.549] process 28465 exited with code 0 after 0.0m I1003 23:26:25.549] Call: gsutil stat gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-e2e/jobResultsCache.json I1003 23:26:26.623] process 28466 exited with code 0 after 0.0m I1003 23:26:26.624] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-e2e/jobResultsCache.json#1570057848337743' I1003 23:26:29.160] process 28608 exited with code 0 after 0.0m I1003 23:26:30.878] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1570057848337743 cp /tmp/gsutil_Tld6LA gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-e2e/jobResultsCache.json I1003 23:26:34.219] process 28752 exited with code 0 after 0.1m I1003 23:26:34.220] Call: gsutil stat gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/jobResultsCache.json I1003 23:26:37.118] process 28930 exited with code 0 after 0.0m I1003 23:26:37.119] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/jobResultsCache.json#1570057851809165' I1003 23:26:39.468] process 29072 exited with code 0 after 0.0m I1003 23:26:39.469] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1570057851809165 cp /tmp/gsutil_Lhm9ly gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/jobResultsCache.json I1003 23:26:41.344] process 29216 exited with code 0 after 0.0m I1003 23:26:41.345] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_wXhj9L gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179880985387339779/finished.json I1003 23:26:43.220] process 29394 exited with code 0 after 0.0m I1003 23:26:43.220] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_QT_NEU gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/latest-build.txt I1003 23:26:47.136] process 29572 exited with code 0 after 0.1m I1003 23:26:47.137] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_v2I45w gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-e2e/latest-build.txt I1003 23:26:49.517] process 29750 exited with code 0 after 0.0m