W1001 17:57:33.773] ************************************************************************** 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 ************************************************************************** I1001 17:57:33.773] Args: --job=pull-azuredisk-csi-driver-sanity --service-account=/etc/service-account/service-account.json --upload=gs://kubernetes-jenkins/logs --job=pull-azuredisk-csi-driver-sanity --root=/go/src --service-account=/etc/service-account/service-account.json --repo=github.com/kubernetes-sigs/azuredisk-csi-driver=master:6b4d4209385f8a3b04a39f1970017a27f2667a9a,166:35f2901acb3478c935a8b603cb4856fe60190383 --upload=gs://kubernetes-upstream/pr-logs --scenario=execute -- make sanity-test I1001 17:57:33.773] Bootstrap pull-azuredisk-csi-driver-sanity... I1001 17:57:33.777] Builder: dedd5914-e474-11e9-918b-16773c0c7aed I1001 17:57:33.777] Image: gcr.io/k8s-testimages/kubekins-e2e:v20190927-21e0205-master I1001 17:57:33.777] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/1179092917625556994 I1001 17:57:33.777] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1001 17:57:34.335] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1001 17:57:34.365] process 32 exited with code 0 after 0.0m I1001 17:57:34.365] Call: gcloud config get-value account I1001 17:57:34.702] process 44 exited with code 0 after 0.0m I1001 17:57:34.702] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1001 17:57:34.703] Root: /go/src I1001 17:57:34.703] cd to /go/src I1001 17:57:34.703] Checkout: /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver master:6b4d4209385f8a3b04a39f1970017a27f2667a9a,166:35f2901acb3478c935a8b603cb4856fe60190383 to /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver I1001 17:57:34.703] Call: git init github.com/kubernetes-sigs/azuredisk-csi-driver I1001 17:57:34.708] Initialized empty Git repository in /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/.git/ I1001 17:57:34.708] process 56 exited with code 0 after 0.0m I1001 17:57:34.709] Call: git config --local user.name 'K8S Bootstrap' I1001 17:57:34.712] process 57 exited with code 0 after 0.0m I1001 17:57:34.712] Call: git config --local user.email k8s_bootstrap@localhost I1001 17:57:34.715] process 58 exited with code 0 after 0.0m I1001 17:57:34.716] Call: git fetch --quiet --tags https://github.com/kubernetes-sigs/azuredisk-csi-driver master +refs/pull/166/head:refs/pr/166 I1001 17:57:42.687] process 59 exited with code 0 after 0.1m I1001 17:57:42.687] Call: git checkout -B test 6b4d4209385f8a3b04a39f1970017a27f2667a9a W1001 17:57:43.150] Switched to a new branch 'test' I1001 17:57:43.153] process 71 exited with code 0 after 0.0m I1001 17:57:43.154] Call: git show -s --format=format:%ct HEAD I1001 17:57:43.157] process 72 exited with code 0 after 0.0m I1001 17:57:43.158] Call: git merge --no-ff -m 'Merge +refs/pull/166/head:refs/pr/166' 35f2901acb3478c935a8b603cb4856fe60190383 I1001 17:57:43.455] Removing test/integration/azure.json I1001 17:57:43.455] Removing test/e2e/run-test.sh I1001 17:57:43.455] Removing .travis.yml I1001 17:57:43.455] Merge made by the 'recursive' strategy. I1001 17:57:43.465] .travis.yml | 36 - I1001 17:57:43.465] Gopkg.lock | 17 +- I1001 17:57:43.465] Makefile | 103 +- I1001 17:57:43.466] hack/verify-all.sh | 2 +- I1001 17:57:43.466] hack/verify-dep.sh | 1 + I1001 17:57:43.466] hack/verify-gofmt.sh | 2 +- I1001 17:57:43.466] hack/verify-golint.sh | 7 +- I1001 17:57:43.466] pkg/azuredisk/controllerserver.go | 2 +- I1001 17:57:43.467] test/e2e/dynamic_provisioning.go | 10 - I1001 17:57:43.467] test/e2e/pre_provisioning.go | 16 +- I1001 17:57:43.467] test/e2e/run-test.sh | 37 - I1001 17:57:43.467] test/e2e/suite_test.go | 87 + I1001 17:57:43.467] test/integration/azure.json | 33 - I1001 17:57:43.467] test/integration/integration_test.go | 90 + I1001 17:57:43.468] test/integration/run-test.sh | 157 +- I1001 17:57:43.468] test/integration/run-tests-all-clouds.sh | 32 +- I1001 17:57:43.468] test/sanity/run-test.sh | 47 +- I1001 17:57:43.468] test/sanity/run-tests-all-clouds.sh | 37 +- I1001 17:57:43.468] test/sanity/sanity_test.go | 72 +- I1001 17:57:43.469] test/utils/azure/azure_helpers.go | 96 + I1001 17:57:43.469] test/utils/credentials/credentials.go | 188 ++ I1001 17:57:43.469] test/utils/credentials/credentials_test.go | 181 ++ I1001 17:57:43.469] test/utils/testutil/testutil.go | 8 + I1001 17:57:43.469] .../resources/mgmt/2018-05-01/resources/client.go | 51 + I1001 17:57:43.470] .../2018-05-01/resources/deploymentoperations.go | 474 +++++ I1001 17:57:43.470] .../mgmt/2018-05-01/resources/deployments.go | 1553 +++++++++++++++ I1001 17:57:43.470] .../resources/mgmt/2018-05-01/resources/groups.go | 676 +++++++ I1001 17:57:43.470] .../resources/mgmt/2018-05-01/resources/models.go | 2044 ++++++++++++++++++++ I1001 17:57:43.470] .../mgmt/2018-05-01/resources/operations.go | 147 ++ I1001 17:57:43.471] .../mgmt/2018-05-01/resources/providers.go | 392 ++++ I1001 17:57:43.471] .../mgmt/2018-05-01/resources/resources.go | 1352 +++++++++++++ I1001 17:57:43.471] .../resources/mgmt/2018-05-01/resources/tags.go | 454 +++++ I1001 17:57:43.471] .../resources/mgmt/2018-05-01/resources/version.go | 30 + I1001 17:57:43.471] vendor/github.com/pelletier/go-toml/LICENSE | 21 + I1001 17:57:43.471] vendor/github.com/pelletier/go-toml/doc.go | 23 + I1001 17:57:43.472] vendor/github.com/pelletier/go-toml/fuzz.go | 31 + I1001 17:57:43.472] vendor/github.com/pelletier/go-toml/keysparsing.go | 113 ++ I1001 17:57:43.472] vendor/github.com/pelletier/go-toml/lexer.go | 752 +++++++ I1001 17:57:43.472] vendor/github.com/pelletier/go-toml/marshal.go | 803 ++++++++ I1001 17:57:43.473] vendor/github.com/pelletier/go-toml/parser.go | 442 +++++ I1001 17:57:43.473] vendor/github.com/pelletier/go-toml/position.go | 29 + I1001 17:57:43.473] vendor/github.com/pelletier/go-toml/token.go | 144 ++ I1001 17:57:43.473] vendor/github.com/pelletier/go-toml/toml.go | 393 ++++ I1001 17:57:43.473] .../pelletier/go-toml/tomltree_create.go | 142 ++ I1001 17:57:43.474] .../github.com/pelletier/go-toml/tomltree_write.go | 434 +++++ I1001 17:57:43.474] .../azure/azure_controller_common.go | 29 +- I1001 17:57:43.474] 46 files changed, 11400 insertions(+), 390 deletions(-) I1001 17:57:43.474] delete mode 100644 .travis.yml I1001 17:57:43.474] delete mode 100755 test/e2e/run-test.sh I1001 17:57:43.474] delete mode 100644 test/integration/azure.json I1001 17:57:43.475] create mode 100644 test/integration/integration_test.go I1001 17:57:43.475] create mode 100644 test/utils/azure/azure_helpers.go I1001 17:57:43.475] create mode 100644 test/utils/credentials/credentials.go I1001 17:57:43.475] create mode 100644 test/utils/credentials/credentials_test.go I1001 17:57:43.475] create mode 100644 test/utils/testutil/testutil.go I1001 17:57:43.476] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/client.go I1001 17:57:43.476] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/deploymentoperations.go I1001 17:57:43.476] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/deployments.go I1001 17:57:43.476] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/groups.go I1001 17:57:43.477] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/models.go I1001 17:57:43.477] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/operations.go I1001 17:57:43.477] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/providers.go I1001 17:57:43.477] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/resources.go I1001 17:57:43.477] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/tags.go I1001 17:57:43.478] create mode 100644 vendor/github.com/Azure/azure-sdk-for-go/services/resources/mgmt/2018-05-01/resources/version.go I1001 17:57:43.478] create mode 100644 vendor/github.com/pelletier/go-toml/LICENSE I1001 17:57:43.478] create mode 100644 vendor/github.com/pelletier/go-toml/doc.go I1001 17:57:43.478] create mode 100644 vendor/github.com/pelletier/go-toml/fuzz.go I1001 17:57:43.478] create mode 100644 vendor/github.com/pelletier/go-toml/keysparsing.go I1001 17:57:43.479] create mode 100644 vendor/github.com/pelletier/go-toml/lexer.go I1001 17:57:43.479] create mode 100644 vendor/github.com/pelletier/go-toml/marshal.go I1001 17:57:43.479] create mode 100644 vendor/github.com/pelletier/go-toml/parser.go I1001 17:57:43.479] create mode 100644 vendor/github.com/pelletier/go-toml/position.go I1001 17:57:43.479] create mode 100644 vendor/github.com/pelletier/go-toml/token.go I1001 17:57:43.479] create mode 100644 vendor/github.com/pelletier/go-toml/toml.go I1001 17:57:43.480] create mode 100644 vendor/github.com/pelletier/go-toml/tomltree_create.go I1001 17:57:43.480] create mode 100644 vendor/github.com/pelletier/go-toml/tomltree_write.go I1001 17:57:43.480] process 73 exited with code 0 after 0.0m I1001 17:57:43.480] Configure environment... I1001 17:57:43.481] Call: git show -s --format=format:%ct HEAD I1001 17:57:43.484] process 75 exited with code 0 after 0.0m I1001 17:57:43.485] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1001 17:57:44.178] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1001 17:57:44.308] process 76 exited with code 0 after 0.0m I1001 17:57:44.309] Call: gcloud config get-value account I1001 17:57:44.565] process 88 exited with code 0 after 0.0m I1001 17:57:44.565] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1001 17:57:44.565] Start 1179092917625556994 at unknown... I1001 17:57:44.567] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_mKJhqX gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/1179092917625556994/started.json I1001 17:57:46.393] process 100 exited with code 0 after 0.0m I1001 17:57:46.394] 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-sanity/1179092917625556994' cp /tmp/gsutil_erxpf_ gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-sanity/1179092917625556994.txt I1001 17:57:47.872] process 278 exited with code 0 after 0.0m I1001 17:57:47.873] Call: /workspace/./test-infra/jenkins/../scenarios/execute.py make sanity-test W1001 17:57:47.894] Run: ('make', 'sanity-test') I1001 17:57:47.995] if [ ! -d ./vendor ]; then dep ensure -vendor-only; fi I1001 17:57:47.995] CGO_ENABLED=0 GOOS=linux go build -a -ldflags "-X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.driverVersion=e2e- -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.gitCommit=9a06ade8e6e1381f88f4332ea800e16364a342d0 -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.buildDate=2019-10-01T17:57:47Z -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 I1001 17:59:53.012] go test -v -timeout=20m ./test/sanity I1001 18:00:14.076] === RUN TestSanity I1001 18:00:14.077] 2019/10/01 18:00:14 Creating resource group azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc in AzurePublicCloud I1001 18:00:16.161] I1001 18:00:16.161] WARNING: apt does not have a stable CLI interface. Use with caution in scripts. I1001 18:00:16.162] I1001 18:00:16.558] Get:3 https://download.docker.com/linux/debian stretch InRelease [44.8 kB] I1001 18:00:16.617] Ign:1 http://cdn-fastly.deb.debian.org/debian stretch InRelease I1001 18:00:16.661] Get:2 http://cdn-fastly.deb.debian.org/debian stretch-updates InRelease [91.0 kB] I1001 18:00:16.737] Get:4 http://security-cdn.debian.org/debian-security stretch/updates InRelease [94.3 kB] I1001 18:00:16.793] Get:5 http://cdn-fastly.deb.debian.org/debian stretch Release [118 kB] I1001 18:00:16.806] Get:6 https://download.docker.com/linux/debian stretch/stable amd64 Packages [10.7 kB] I1001 18:00:16.883] Get:7 http://cdn-fastly.deb.debian.org/debian stretch Release.gpg [2365 B] I1001 18:00:16.927] Get:8 http://cdn-fastly.deb.debian.org/debian stretch-updates/main amd64 Packages [27.4 kB] I1001 18:00:17.002] Get:9 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 Packages [499 kB] I1001 18:00:17.107] Get:10 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 Packages [7086 kB] I1001 18:00:18.528] Fetched 7974 kB in 2s (3433 kB/s) I1001 18:00:19.176] Reading package lists... I1001 18:00:19.335] Building dependency tree... I1001 18:00:19.335] Reading state information... I1001 18:00:19.343] 26 packages can be upgraded. Run 'apt list --upgradable' to see them. I1001 18:00:19.348] I1001 18:00:19.348] WARNING: apt does not have a stable CLI interface. Use with caution in scripts. I1001 18:00:19.348] I1001 18:00:20.075] Reading package lists... I1001 18:00:20.269] Building dependency tree... I1001 18:00:20.271] Reading state information... I1001 18:00:20.350] procps is already the newest version (2:3.3.12-3+deb9u1). I1001 18:00:20.351] The following additional packages will be installed: I1001 18:00:20.351] libavahi-client3 libavahi-common-data libavahi-common3 libcups2 libldb1 I1001 18:00:20.351] libtalloc2 libtdb1 libtevent0 libwbclient0 python-crypto python-ldb I1001 18:00:20.351] python-samba python-talloc python-tdb samba-common samba-common-bin I1001 18:00:20.352] samba-libs I1001 18:00:20.352] Suggested packages: I1001 18:00:20.352] keyutils smbclient winbind cups-common python-crypto-dbg python-crypto-doc I1001 18:00:20.352] python-gpgme heimdal-clients I1001 18:00:20.592] The following NEW packages will be installed: I1001 18:00:20.593] cifs-utils libavahi-client3 libavahi-common-data libavahi-common3 libcups2 I1001 18:00:20.593] libldb1 libtalloc2 libtdb1 libtevent0 libwbclient0 python-crypto python-ldb I1001 18:00:20.593] python-samba python-talloc python-tdb samba-common samba-common-bin I1001 18:00:20.593] samba-libs I1001 18:00:20.870] 0 upgraded, 18 newly installed, 0 to remove and 26 not upgraded. I1001 18:00:20.870] Need to get 8646 kB of archives. I1001 18:00:20.870] After this operation, 38.4 MB of additional disk space will be used. I1001 18:00:20.870] Get:1 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libwbclient0 amd64 2:4.5.16+dfsg-1+deb9u2 [124 kB] I1001 18:00:21.043] Get:2 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 samba-common all 2:4.5.16+dfsg-1+deb9u2 [174 kB] I1001 18:00:21.087] Get:3 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtalloc2 amd64 2.1.8-1 [36.3 kB] I1001 18:00:21.088] Get:4 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 cifs-utils amd64 2:6.7-1 [75.8 kB] I1001 18:00:21.090] Get:5 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libavahi-common-data amd64 0.6.32-2 [118 kB] I1001 18:00:21.130] Get:6 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libavahi-common3 amd64 0.6.32-2 [52.0 kB] I1001 18:00:21.131] Get:7 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libavahi-client3 amd64 0.6.32-2 [55.3 kB] I1001 18:00:21.132] Get:8 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libcups2 amd64 2.2.1-8+deb9u4 [307 kB] I1001 18:00:21.136] Get:9 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtdb1 amd64 1.3.11-2 [43.2 kB] I1001 18:00:21.136] Get:10 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtevent0 amd64 0.9.31-1 [29.3 kB] I1001 18:00:21.137] Get:11 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libldb1 amd64 2:1.1.27-1+deb9u1 [113 kB] I1001 18:00:21.173] Get:12 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-crypto amd64 2.6.1-7 [259 kB] I1001 18:00:21.176] Get:13 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-ldb amd64 2:1.1.27-1+deb9u1 [34.8 kB] I1001 18:00:21.177] Get:14 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-tdb amd64 1.3.11-2 [16.2 kB] I1001 18:00:21.178] Get:15 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-talloc amd64 2.1.8-1 [11.9 kB] I1001 18:00:21.178] Get:16 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 samba-libs amd64 2:4.5.16+dfsg-1+deb9u2 [5231 kB] I1001 18:00:21.308] Get:17 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-samba amd64 2:4.5.16+dfsg-1+deb9u2 [1360 kB] I1001 18:00:21.352] Get:18 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 samba-common-bin amd64 2:4.5.16+dfsg-1+deb9u2 [603 kB] I1001 18:00:27.570] debconf: delaying package configuration, since apt-utils is not installed I1001 18:00:28.296] Fetched 8646 kB in 0s (11.4 MB/s) I1001 18:00:28.384] Selecting previously unselected package libwbclient0:amd64. I1001 18:00:28.461] (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 ... 19609 files and directories currently installed.) I1001 18:00:28.462] Preparing to unpack .../00-libwbclient0_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1001 18:00:28.496] Unpacking libwbclient0:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:28.664] Selecting previously unselected package samba-common. I1001 18:00:28.667] Preparing to unpack .../01-samba-common_2%3a4.5.16+dfsg-1+deb9u2_all.deb ... I1001 18:00:28.690] Unpacking samba-common (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:28.834] Selecting previously unselected package libtalloc2:amd64. I1001 18:00:28.837] Preparing to unpack .../02-libtalloc2_2.1.8-1_amd64.deb ... I1001 18:00:28.852] Unpacking libtalloc2:amd64 (2.1.8-1) ... I1001 18:00:28.975] Selecting previously unselected package cifs-utils. I1001 18:00:28.978] Preparing to unpack .../03-cifs-utils_2%3a6.7-1_amd64.deb ... I1001 18:00:28.994] Unpacking cifs-utils (2:6.7-1) ... I1001 18:00:29.112] Selecting previously unselected package libavahi-common-data:amd64. I1001 18:00:29.114] Preparing to unpack .../04-libavahi-common-data_0.6.32-2_amd64.deb ... I1001 18:00:29.129] Unpacking libavahi-common-data:amd64 (0.6.32-2) ... I1001 18:00:29.341] Selecting previously unselected package libavahi-common3:amd64. I1001 18:00:29.343] Preparing to unpack .../05-libavahi-common3_0.6.32-2_amd64.deb ... I1001 18:00:29.370] Unpacking libavahi-common3:amd64 (0.6.32-2) ... I1001 18:00:29.594] Selecting previously unselected package libavahi-client3:amd64. I1001 18:00:29.598] Preparing to unpack .../06-libavahi-client3_0.6.32-2_amd64.deb ... I1001 18:00:29.620] Unpacking libavahi-client3:amd64 (0.6.32-2) ... I1001 18:00:29.802] Selecting previously unselected package libcups2:amd64. I1001 18:00:29.806] Preparing to unpack .../07-libcups2_2.2.1-8+deb9u4_amd64.deb ... I1001 18:00:29.834] Unpacking libcups2:amd64 (2.2.1-8+deb9u4) ... I1001 18:00:30.098] Selecting previously unselected package libtdb1:amd64. I1001 18:00:30.114] Preparing to unpack .../08-libtdb1_1.3.11-2_amd64.deb ... I1001 18:00:30.134] Unpacking libtdb1:amd64 (1.3.11-2) ... I1001 18:00:30.310] Selecting previously unselected package libtevent0:amd64. I1001 18:00:30.313] Preparing to unpack .../09-libtevent0_0.9.31-1_amd64.deb ... I1001 18:00:30.334] Unpacking libtevent0:amd64 (0.9.31-1) ... I1001 18:00:30.701] Selecting previously unselected package libldb1:amd64. I1001 18:00:30.704] Preparing to unpack .../10-libldb1_2%3a1.1.27-1+deb9u1_amd64.deb ... I1001 18:00:30.718] Unpacking libldb1:amd64 (2:1.1.27-1+deb9u1) ... I1001 18:00:30.853] Selecting previously unselected package python-crypto. I1001 18:00:30.857] Preparing to unpack .../11-python-crypto_2.6.1-7_amd64.deb ... I1001 18:00:30.874] Unpacking python-crypto (2.6.1-7) ... I1001 18:00:31.074] Selecting previously unselected package python-ldb. I1001 18:00:31.077] Preparing to unpack .../12-python-ldb_2%3a1.1.27-1+deb9u1_amd64.deb ... I1001 18:00:31.094] Unpacking python-ldb (2:1.1.27-1+deb9u1) ... I1001 18:00:31.220] Selecting previously unselected package python-tdb. I1001 18:00:31.222] Preparing to unpack .../13-python-tdb_1.3.11-2_amd64.deb ... I1001 18:00:31.239] Unpacking python-tdb (1.3.11-2) ... I1001 18:00:31.371] Selecting previously unselected package python-talloc. I1001 18:00:31.374] Preparing to unpack .../14-python-talloc_2.1.8-1_amd64.deb ... I1001 18:00:31.391] Unpacking python-talloc (2.1.8-1) ... I1001 18:00:31.529] Selecting previously unselected package samba-libs:amd64. I1001 18:00:31.531] Preparing to unpack .../15-samba-libs_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1001 18:00:31.552] Unpacking samba-libs:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:32.480] Selecting previously unselected package python-samba. I1001 18:00:32.483] Preparing to unpack .../16-python-samba_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1001 18:00:32.512] Unpacking python-samba (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:32.879] Selecting previously unselected package samba-common-bin. I1001 18:00:32.882] Preparing to unpack .../17-samba-common-bin_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1001 18:00:32.912] Unpacking samba-common-bin (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:33.272] Setting up libtdb1:amd64 (1.3.11-2) ... I1001 18:00:33.386] Setting up libwbclient0:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:33.475] Setting up python-crypto (2.6.1-7) ... I1001 18:00:34.020] Setting up python-tdb (1.3.11-2) ... I1001 18:00:34.547] Setting up samba-common (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:34.845] debconf: unable to initialize frontend: Dialog I1001 18:00:34.845] debconf: (No usable dialog-like program is installed, so the dialog based frontend cannot be used. at /usr/share/perl5/Debconf/FrontEnd/Dialog.pm line 76.) I1001 18:00:34.845] debconf: falling back to frontend: Readline I1001 18:00:34.954] I1001 18:00:34.954] Creating config file /etc/samba/smb.conf with new version I1001 18:00:35.106] Processing triggers for libc-bin (2.24-11+deb9u4) ... I1001 18:00:35.465] Setting up libtalloc2:amd64 (2.1.8-1) ... I1001 18:00:35.602] Setting up libavahi-common-data:amd64 (0.6.32-2) ... I1001 18:00:35.670] Setting up python-talloc (2.1.8-1) ... I1001 18:00:35.762] Setting up cifs-utils (2:6.7-1) ... I1001 18:00:35.911] update-alternatives: using /usr/lib/x86_64-linux-gnu/cifs-utils/idmapwb.so to provide /etc/cifs-utils/idmap-plugin (idmap-plugin) in auto mode I1001 18:00:35.962] Setting up libtevent0:amd64 (0.9.31-1) ... I1001 18:00:36.055] Setting up libavahi-common3:amd64 (0.6.32-2) ... I1001 18:00:36.148] Setting up libldb1:amd64 (2:1.1.27-1+deb9u1) ... I1001 18:00:36.230] Setting up libavahi-client3:amd64 (0.6.32-2) ... I1001 18:00:36.328] Setting up libcups2:amd64 (2.2.1-8+deb9u4) ... I1001 18:00:36.406] Setting up python-ldb (2:1.1.27-1+deb9u1) ... I1001 18:00:36.971] Setting up samba-libs:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:37.073] Setting up python-samba (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:37.937] Setting up samba-common-bin (2:4.5.16+dfsg-1+deb9u2) ... I1001 18:00:38.024] Processing triggers for libc-bin (2.24-11+deb9u4) ... I1001 18:00:38.237] Installing CSI sanity test binary... I1001 18:00:38.238] Cloning into 'csi-test'... I1001 18:00:39.268] Note: checking out '5b1e3786b7c8f7ca514b40e882a0b5dc36e4c842'. I1001 18:00:39.268] I1001 18:00:39.268] You are in 'detached HEAD' state. You can look around, make experimental I1001 18:00:39.268] changes and commit them, and you can discard any commits you make in this I1001 18:00:39.268] state without impacting any branches by performing another checkout. I1001 18:00:39.268] I1001 18:00:39.268] If you want to create a new branch to retain commits you create, you may I1001 18:00:39.269] do so (now or later) by using -b with the checkout command again. Example: I1001 18:00:39.269] I1001 18:00:39.269] git checkout -b I1001 18:00:39.269] I1001 18:00:39.396] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/csi-test/cmd/csi-sanity /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver I1001 18:00:39.397] make[1]: Entering directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/csi-test/cmd/csi-sanity' I1001 18:00:39.429] go test -ldflags "-w -X github.com/kubernetes-csi/csi-test/cmd/csi-sanity.VERSION=v1.1.0-HEAD -extldflags '-z relro -z now'" -c -o csi-sanity I1001 18:00:43.610] make[1]: Leaving directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/csi-test/cmd/csi-sanity' I1001 18:00:43.610] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver I1001 18:00:43.612] Begin to run sanity test... I1001 18:00:43.626] Running Suite: CSI Driver Test Suite I1001 18:00:43.627] ==================================== I1001 18:00:43.627] Random Seed: 1569952843 I1001 18:00:43.627] Will run 56 of 57 specs I1001 18:00:43.627] I1001 18:00:43.627] Identity Service GetPluginCapabilities I1001 18:00:43.628] should return appropriate capabilities I1001 18:00:43.628] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/identity.go:43 I1001 18:00:43.628] STEP: connecting to CSI driver I1001 18:00:43.630] I1001 18:00:43.629825 8886 main.go:84] set up prometheus server on [::]:10252 I1001 18:00:43.630] I1001 18:00:43.630082 8886 azuredisk.go:106] I1001 18:00:43.630] DRIVER INFORMATION: I1001 18:00:43.630] ------------------- I1001 18:00:43.630] Build Date: "2019-10-01T17:57:47Z" I1001 18:00:43.630] Compiler: gc I1001 18:00:43.631] Driver Name: disk.csi.azure.com I1001 18:00:43.631] Driver Version: e2e- I1001 18:00:43.631] Git Commit: 9a06ade8e6e1381f88f4332ea800e16364a342d0 I1001 18:00:43.631] Go Version: go1.12.10 I1001 18:00:43.631] Platform: linux/amd64 I1001 18:00:43.632] Topology Key: topology.disk.csi.azure.com/zone I1001 18:00:43.632] I1001 18:00:43.632] Streaming logs below: I1001 18:00:43.632] I1001 18:00:43.630351 8886 azure.go:31] AZURE_CREDENTIAL_FILE env var set as /tmp/azure.json I1001 18:00:43.632] I1001 18:00:43.630728 8886 azure_auth.go:99] azure: using client_id+client_secret to retrieve access token I1001 18:00:43.633] I1001 18:00:43.630983 8886 mount_linux.go:160] Detected OS without systemd I1001 18:00:43.633] I1001 18:00:43.631002 8886 driver.go:80] Enabling controller service capability: CREATE_DELETE_VOLUME I1001 18:00:43.633] I1001 18:00:43.631006 8886 driver.go:80] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I1001 18:00:43.633] I1001 18:00:43.631010 8886 driver.go:80] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I1001 18:00:43.634] I1001 18:00:43.631015 8886 driver.go:80] Enabling controller service capability: LIST_SNAPSHOTS I1001 18:00:43.634] I1001 18:00:43.631021 8886 driver.go:99] Enabling volume access mode: SINGLE_NODE_WRITER I1001 18:00:43.634] I1001 18:00:43.631027 8886 driver.go:90] Enabling node service capability: STAGE_UNSTAGE_VOLUME I1001 18:00:43.634] I1001 18:00:43.631148 8886 server.go:103] Listening for connections on address: &net.UnixAddr{Name:"//tmp/csi.sock", Net:"unix"} I1001 18:00:44.628] STEP: creating mount and staging directories I1001 18:00:44.629] I1001 18:00:44.629246 8886 utils.go:112] GRPC call: /csi.v1.Identity/GetPluginCapabilities I1001 18:00:44.629] I1001 18:00:44.629289 8886 utils.go:113] GRPC request: I1001 18:00:44.629] I1001 18:00:44.629301 8886 identityserver.go:59] Using default capabilities I1001 18:00:44.630] I1001 18:00:44.629322 8886 utils.go:119] GRPC response: capabilities: > I1001 18:00:44.630] STEP: checking successful response I1001 18:00:44.630] • I1001 18:00:44.630] ------------------------------ I1001 18:00:44.630] Identity Service Probe I1001 18:00:44.630] should return appropriate information I1001 18:00:44.630] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/identity.go:65 I1001 18:00:44.631] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:00:44.631] STEP: creating mount and staging directories I1001 18:00:44.631] I1001 18:00:44.630833 8886 utils.go:112] GRPC call: /csi.v1.Identity/Probe I1001 18:00:44.631] I1001 18:00:44.630854 8886 utils.go:113] GRPC request: I1001 18:00:44.631] I1001 18:00:44.630860 8886 utils.go:119] GRPC response: ready: I1001 18:00:44.632] STEP: verifying return status I1001 18:00:44.632] • I1001 18:00:44.632] ------------------------------ I1001 18:00:44.632] Identity Service GetPluginInfo I1001 18:00:44.632] should return appropriate information I1001 18:00:44.633] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/identity.go:85 I1001 18:00:44.633] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:00:44.633] STEP: creating mount and staging directories I1001 18:00:44.633] I1001 18:00:44.631403 8886 utils.go:112] GRPC call: /csi.v1.Identity/GetPluginInfo I1001 18:00:44.633] I1001 18:00:44.631460 8886 utils.go:113] GRPC request: I1001 18:00:44.634] I1001 18:00:44.631492 8886 identityserver.go:33] Using default GetPluginInfo I1001 18:00:44.634] I1001 18:00:44.631508 8886 utils.go:119] GRPC response: name:"disk.csi.azure.com" vendor_version:"e2e-" I1001 18:00:44.634] STEP: verifying name size and characters I1001 18:00:44.634] • I1001 18:00:44.634] ------------------------------ I1001 18:00:44.635] ListSnapshots [Controller Server] I1001 18:00:44.635] should return appropriate values (no optional values added) I1001 18:00:44.635] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1186 I1001 18:00:44.635] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:00:44.635] STEP: creating mount and staging directories I1001 18:00:44.635] I1001 18:00:44.632409 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:00:44.636] I1001 18:00:44.632442 8886 utils.go:113] GRPC request: I1001 18:00:44.636] I1001 18:00:44.632450 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:00:44.636] I1001 18:00:44.632456 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:00:44.636] I1001 18:00:44.633524 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:00:44.636] I1001 18:00:44.633586 8886 utils.go:113] GRPC request: I1001 18:00:44.637] I1001 18:00:44.633613 8886 controllerserver.go:518] ListSnapshots called with request {0 {} [] 0} I1001 18:00:45.322] I1001 18:00:45.322639 8886 utils.go:119] GRPC response: next_token:"0" I1001 18:00:45.323] • I1001 18:00:45.323] ------------------------------ I1001 18:00:45.323] ListSnapshots [Controller Server] I1001 18:00:45.323] should return snapshots that match the specify snapshot id I1001 18:00:45.323] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1198 I1001 18:00:45.324] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:00:45.324] STEP: creating mount and staging directories I1001 18:00:45.324] I1001 18:00:45.323268 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:00:45.324] I1001 18:00:45.323329 8886 utils.go:113] GRPC request: I1001 18:00:45.324] I1001 18:00:45.323347 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:00:45.325] I1001 18:00:45.323352 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:00:45.325] STEP: creating a volume I1001 18:00:45.325] I1001 18:00:45.324225 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:00:45.325] I1001 18:00:45.324257 8886 utils.go:113] GRPC request: name:"listSnapshots-volume-1" capacity_range: volume_capabilities: access_mode: > I1001 18:00:45.442] I1001 18:00:45.441800 8886 controllerserver.go:175] begin to create azure disk(listSnapshots-volume-1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:00:45.442] I1001 18:00:45.441832 8886 azuredisk.go:244] azureDisk - creating new managed Name:listSnapshots-volume-1 StorageAccountType:Standard_LRS Size:10 I1001 18:00:51.693] I1001 18:00:51.693190 8886 azuredisk.go:348] azureDisk - created new MD Name:listSnapshots-volume-1 StorageAccountType:Standard_LRS Size:10 I1001 18:00:51.693] I1001 18:00:51.693221 8886 controllerserver.go:222] create azure disk(listSnapshots-volume-1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:00:51.694] I1001 18:00:51.693230 8886 utils.go:119] GRPC response: volume: > > I1001 18:00:51.694] STEP: creating a snapshot I1001 18:00:51.694] I1001 18:00:51.694034 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:00:51.694] I1001 18:00:51.694086 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-1" name:"listSnapshots-snapshot-1" I1001 18:00:51.695] I1001 18:00:51.694100 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-1 listSnapshots-snapshot-1 map[] map[] {} [] 0} I1001 18:00:51.695] I1001 18:00:51.694126 8886 controllerserver.go:463] begin to create snapshot(listSnapshots-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:01:02.350] I1001 18:01:02.350298 8886 controllerserver.go:476] create snapshot(listSnapshots-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:01:02.434] I1001 18:01:02.433910 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:01:02.435] I1001 18:01:02.434722 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:01:02.435] I1001 18:01:02.434752 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-1" I1001 18:01:02.435] I1001 18:01:02.434762 8886 controllerserver.go:518] ListSnapshots called with request {0 /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-1 {} [] 0} I1001 18:01:02.519] I1001 18:01:02.518816 8886 utils.go:119] GRPC response: entries: ready_to_use:true > > I1001 18:01:02.522] STEP: cleaning up deleting the snapshot I1001 18:01:02.522] I1001 18:01:02.522304 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:01:02.522] I1001 18:01:02.522441 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-1" I1001 18:01:02.523] I1001 18:01:02.522468 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-1 map[] {} [] 0} I1001 18:01:02.523] I1001 18:01:02.522527 8886 controllerserver.go:503] begin to delete snapshot(listSnapshots-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:01:07.940] I1001 18:01:07.939939 8886 controllerserver.go:512] delete snapshot(listSnapshots-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:01:07.940] I1001 18:01:07.939975 8886 utils.go:119] GRPC response: I1001 18:01:07.940] STEP: cleaning up deleting the volume I1001 18:01:07.941] I1001 18:01:07.940847 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:01:07.941] I1001 18:01:07.940884 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-1" I1001 18:01:07.941] I1001 18:01:07.940903 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-1) I1001 18:01:13.378] I1001 18:01:13.378177 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-1 I1001 18:01:13.379] I1001 18:01:13.378216 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-1) successfully I1001 18:01:13.379] I1001 18:01:13.378232 8886 utils.go:119] GRPC response: I1001 18:01:13.379] I1001 18:01:13.379] • [SLOW TEST:28.056 seconds] I1001 18:01:13.380] ListSnapshots [Controller Server] I1001 18:01:13.380] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:01:13.380] should return snapshots that match the specify snapshot id I1001 18:01:13.380] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1198 I1001 18:01:13.381] ------------------------------ I1001 18:01:13.381] ListSnapshots [Controller Server] I1001 18:01:13.381] should return empty when the specify snapshot id is not exist I1001 18:01:13.381] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1230 I1001 18:01:13.382] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:01:13.382] STEP: creating mount and staging directories I1001 18:01:13.382] I1001 18:01:13.379100 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:01:13.382] I1001 18:01:13.379148 8886 utils.go:113] GRPC request: I1001 18:01:13.382] I1001 18:01:13.379156 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:01:13.383] I1001 18:01:13.379160 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:01:13.383] I1001 18:01:13.379674 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:01:13.383] I1001 18:01:13.379702 8886 utils.go:113] GRPC request: snapshot_id:"none-exist-id" I1001 18:01:13.384] I1001 18:01:13.379710 8886 controllerserver.go:518] ListSnapshots called with request {0 none-exist-id {} [] 0} I1001 18:01:13.496] I1001 18:01:13.496279 8886 utils.go:119] GRPC response: I1001 18:01:13.496] • I1001 18:01:13.497] ------------------------------ I1001 18:01:13.497] ListSnapshots [Controller Server] I1001 18:01:13.497] should return snapshots that match the specify source volume id) I1001 18:01:13.497] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1240 I1001 18:01:13.498] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:01:13.498] STEP: creating mount and staging directories I1001 18:01:13.498] I1001 18:01:13.496726 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:01:13.498] I1001 18:01:13.496759 8886 utils.go:113] GRPC request: I1001 18:01:13.499] I1001 18:01:13.496766 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:01:13.499] I1001 18:01:13.496770 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:01:13.499] STEP: creating a volume I1001 18:01:13.499] I1001 18:01:13.497470 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:01:13.500] I1001 18:01:13.497503 8886 utils.go:113] GRPC request: name:"listSnapshots-volume-2" capacity_range: volume_capabilities: access_mode: > I1001 18:01:13.594] I1001 18:01:13.593887 8886 controllerserver.go:175] begin to create azure disk(listSnapshots-volume-2) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:01:13.594] I1001 18:01:13.593915 8886 azuredisk.go:244] azureDisk - creating new managed Name:listSnapshots-volume-2 StorageAccountType:Standard_LRS Size:10 I1001 18:01:24.323] I1001 18:01:24.323588 8886 azuredisk.go:348] azureDisk - created new MD Name:listSnapshots-volume-2 StorageAccountType:Standard_LRS Size:10 I1001 18:01:24.324] I1001 18:01:24.323632 8886 controllerserver.go:222] create azure disk(listSnapshots-volume-2) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:01:24.325] I1001 18:01:24.323645 8886 utils.go:119] GRPC response: volume: > > I1001 18:01:24.325] STEP: creating a snapshot I1001 18:01:24.325] I1001 18:01:24.324433 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:01:24.325] I1001 18:01:24.324477 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2" name:"listSnapshots-snapshot-2" I1001 18:01:24.326] I1001 18:01:24.324495 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2 listSnapshots-snapshot-2 map[] map[] {} [] 0} I1001 18:01:24.326] I1001 18:01:24.324525 8886 controllerserver.go:463] begin to create snapshot(listSnapshots-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:01:40.077] I1001 18:01:40.077475 8886 controllerserver.go:476] create snapshot(listSnapshots-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:01:40.163] I1001 18:01:40.162519 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:01:40.163] I1001 18:01:40.163073 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:01:40.163] I1001 18:01:40.163098 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2" I1001 18:01:40.163] I1001 18:01:40.163109 8886 controllerserver.go:518] ListSnapshots called with request {0 /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2 {} [] 0} I1001 18:01:40.297] I1001 18:01:40.297282 8886 utils.go:119] GRPC response: entries: ready_to_use:true > > next_token:"0" I1001 18:01:40.298] STEP: cleaning up deleting the snapshot I1001 18:01:40.298] I1001 18:01:40.297809 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:01:40.298] I1001 18:01:40.297831 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-2" I1001 18:01:40.298] I1001 18:01:40.297841 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-2 map[] {} [] 0} I1001 18:01:40.298] I1001 18:01:40.297896 8886 controllerserver.go:503] begin to delete snapshot(listSnapshots-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:01:45.768] I1001 18:01:45.767854 8886 controllerserver.go:512] delete snapshot(listSnapshots-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:01:45.768] I1001 18:01:45.767897 8886 utils.go:119] GRPC response: I1001 18:01:45.768] STEP: cleaning up deleting the volume I1001 18:01:45.769] I1001 18:01:45.768560 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:01:45.769] I1001 18:01:45.768591 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2" I1001 18:01:45.769] I1001 18:01:45.768615 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2) I1001 18:01:51.252] I1001 18:01:51.252306 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2 I1001 18:01:51.253] I1001 18:01:51.252336 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-2) successfully I1001 18:01:51.253] I1001 18:01:51.252345 8886 utils.go:119] GRPC response: I1001 18:01:51.253] I1001 18:01:51.253] • [SLOW TEST:37.756 seconds] I1001 18:01:51.253] ListSnapshots [Controller Server] I1001 18:01:51.253] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:01:51.254] should return snapshots that match the specify source volume id) I1001 18:01:51.254] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1240 I1001 18:01:51.254] ------------------------------ I1001 18:01:51.254] ListSnapshots [Controller Server] I1001 18:01:51.254] should return empty when the specify source volume id is not exist I1001 18:01:51.254] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1273 I1001 18:01:51.255] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:01:51.255] STEP: creating mount and staging directories I1001 18:01:51.255] I1001 18:01:51.252874 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:01:51.255] I1001 18:01:51.252896 8886 utils.go:113] GRPC request: I1001 18:01:51.255] I1001 18:01:51.252903 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:01:51.256] I1001 18:01:51.252909 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:01:51.256] I1001 18:01:51.253294 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:01:51.256] I1001 18:01:51.253311 8886 utils.go:113] GRPC request: source_volume_id:"none-exist-volume-id" I1001 18:01:51.256] I1001 18:01:51.253316 8886 controllerserver.go:518] ListSnapshots called with request {0 none-exist-volume-id {} [] 0} I1001 18:01:51.459] I1001 18:01:51.459417 8886 utils.go:119] GRPC response: I1001 18:01:51.459] • I1001 18:01:51.460] ------------------------------ I1001 18:01:51.460] ListSnapshots [Controller Server] I1001 18:01:51.460] check the presence of new snapshots in the snapshot list I1001 18:01:51.460] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1283 I1001 18:01:51.460] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:01:51.460] STEP: creating mount and staging directories I1001 18:01:51.461] I1001 18:01:51.459980 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:01:51.461] I1001 18:01:51.460008 8886 utils.go:113] GRPC request: I1001 18:01:51.461] I1001 18:01:51.460016 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:01:51.461] I1001 18:01:51.460023 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:01:51.461] I1001 18:01:51.460403 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:01:51.461] I1001 18:01:51.460429 8886 utils.go:113] GRPC request: I1001 18:01:51.461] I1001 18:01:51.460437 8886 controllerserver.go:518] ListSnapshots called with request {0 {} [] 0} I1001 18:01:51.559] I1001 18:01:51.559579 8886 utils.go:119] GRPC response: next_token:"0" I1001 18:01:51.559] STEP: creating a volume I1001 18:01:51.560] I1001 18:01:51.559984 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:01:51.560] I1001 18:01:51.560009 8886 utils.go:113] GRPC request: name:"listSnapshots-volume-3" capacity_range: volume_capabilities: access_mode: > I1001 18:01:51.659] I1001 18:01:51.659422 8886 controllerserver.go:175] begin to create azure disk(listSnapshots-volume-3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:01:51.659] I1001 18:01:51.659443 8886 azuredisk.go:244] azureDisk - creating new managed Name:listSnapshots-volume-3 StorageAccountType:Standard_LRS Size:10 I1001 18:02:02.363] I1001 18:02:02.362783 8886 azuredisk.go:348] azureDisk - created new MD Name:listSnapshots-volume-3 StorageAccountType:Standard_LRS Size:10 I1001 18:02:02.363] I1001 18:02:02.362842 8886 controllerserver.go:222] create azure disk(listSnapshots-volume-3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:02:02.363] I1001 18:02:02.362856 8886 utils.go:119] GRPC response: volume: > > I1001 18:02:02.364] STEP: creating a snapshot I1001 18:02:02.364] I1001 18:02:02.363523 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:02:02.364] I1001 18:02:02.363556 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-3" name:"listSnapshots-snapshot-3" I1001 18:02:02.364] I1001 18:02:02.363568 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-3 listSnapshots-snapshot-3 map[] map[] {} [] 0} I1001 18:02:02.365] I1001 18:02:02.363592 8886 controllerserver.go:463] begin to create snapshot(listSnapshots-snapshot-3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:02:12.950] I1001 18:02:12.950205 8886 controllerserver.go:476] create snapshot(listSnapshots-snapshot-3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:02:13.067] I1001 18:02:13.066620 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:02:13.068] I1001 18:02:13.067807 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:02:13.068] I1001 18:02:13.067856 8886 utils.go:113] GRPC request: I1001 18:02:13.068] I1001 18:02:13.067869 8886 controllerserver.go:518] ListSnapshots called with request {0 {} [] 0} I1001 18:02:13.163] I1001 18:02:13.162664 8886 utils.go:119] GRPC response: entries: ready_to_use:true > > next_token:"0" I1001 18:02:13.163] STEP: cleaning up deleting the snapshot I1001 18:02:13.163] I1001 18:02:13.163216 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:02:13.163] I1001 18:02:13.163240 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-3" I1001 18:02:13.164] I1001 18:02:13.163250 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/listSnapshots-snapshot-3 map[] {} [] 0} I1001 18:02:13.164] I1001 18:02:13.163283 8886 controllerserver.go:503] begin to delete snapshot(listSnapshots-snapshot-3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:02:18.601] I1001 18:02:18.601297 8886 controllerserver.go:512] delete snapshot(listSnapshots-snapshot-3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:02:18.602] I1001 18:02:18.601345 8886 utils.go:119] GRPC response: I1001 18:02:18.602] STEP: cleaning up deleting the volume I1001 18:02:18.602] I1001 18:02:18.602004 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:02:18.603] I1001 18:02:18.602050 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-3" I1001 18:02:18.603] I1001 18:02:18.602068 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-3) I1001 18:02:24.052] I1001 18:02:24.051966 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-3 I1001 18:02:24.053] I1001 18:02:24.052010 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/listSnapshots-volume-3) successfully I1001 18:02:24.053] I1001 18:02:24.052024 8886 utils.go:119] GRPC response: I1001 18:02:24.053] I1001 18:02:24.052593 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:02:24.053] I1001 18:02:24.052644 8886 utils.go:113] GRPC request: I1001 18:02:24.054] I1001 18:02:24.052656 8886 controllerserver.go:518] ListSnapshots called with request {0 {} [] 0} I1001 18:02:24.193] I1001 18:02:24.193105 8886 utils.go:119] GRPC response: next_token:"0" I1001 18:02:24.193] I1001 18:02:24.193] • [SLOW TEST:32.734 seconds] I1001 18:02:24.194] ListSnapshots [Controller Server] I1001 18:02:24.194] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:02:24.194] check the presence of new snapshots in the snapshot list I1001 18:02:24.194] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1283 I1001 18:02:24.195] ------------------------------ I1001 18:02:24.195] ListSnapshots [Controller Server] I1001 18:02:24.195] should return next token when a limited number of entries are requested I1001 18:02:24.195] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1331 I1001 18:02:24.195] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:02:24.195] STEP: creating mount and staging directories I1001 18:02:24.196] I1001 18:02:24.193826 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:02:24.196] I1001 18:02:24.193854 8886 utils.go:113] GRPC request: I1001 18:02:24.196] I1001 18:02:24.193863 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:02:24.196] I1001 18:02:24.193869 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:02:24.196] I1001 18:02:24.194422 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:02:24.197] I1001 18:02:24.194446 8886 utils.go:113] GRPC request: I1001 18:02:24.197] I1001 18:02:24.194456 8886 controllerserver.go:518] ListSnapshots called with request {0 {} [] 0} I1001 18:02:24.288] I1001 18:02:24.288293 8886 utils.go:119] GRPC response: next_token:"0" I1001 18:02:24.288] STEP: creating required new volumes I1001 18:02:24.289] I1001 18:02:24.288867 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:02:24.289] I1001 18:02:24.288900 8886 utils.go:113] GRPC request: name:"volume1" capacity_range: volume_capabilities: access_mode: > I1001 18:02:24.386] I1001 18:02:24.386227 8886 controllerserver.go:175] begin to create azure disk(volume1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:02:24.386] I1001 18:02:24.386260 8886 azuredisk.go:244] azureDisk - creating new managed Name:volume1 StorageAccountType:Standard_LRS Size:10 I1001 18:02:37.247] I1001 18:02:37.247556 8886 azuredisk.go:348] azureDisk - created new MD Name:volume1 StorageAccountType:Standard_LRS Size:10 I1001 18:02:37.248] I1001 18:02:37.247612 8886 controllerserver.go:222] create azure disk(volume1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:02:37.248] I1001 18:02:37.247629 8886 utils.go:119] GRPC response: volume: > > I1001 18:02:37.249] I1001 18:02:37.248329 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:02:37.249] I1001 18:02:37.248354 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume1" name:"snapshot1" I1001 18:02:37.249] I1001 18:02:37.248364 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume1 snapshot1 map[] map[] {} [] 0} I1001 18:02:37.250] I1001 18:02:37.248395 8886 controllerserver.go:463] begin to create snapshot(snapshot1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:02:48.037] I1001 18:02:48.036881 8886 controllerserver.go:476] create snapshot(snapshot1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:02:48.128] I1001 18:02:48.127577 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:02:48.128] I1001 18:02:48.128396 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:02:48.128] I1001 18:02:48.128432 8886 utils.go:113] GRPC request: name:"volume2" capacity_range: volume_capabilities: access_mode: > I1001 18:02:48.235] I1001 18:02:48.235402 8886 controllerserver.go:175] begin to create azure disk(volume2) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:02:48.236] I1001 18:02:48.235441 8886 azuredisk.go:244] azureDisk - creating new managed Name:volume2 StorageAccountType:Standard_LRS Size:10 I1001 18:02:48.826] I1001 18:02:48.826590 8886 azuredisk.go:348] azureDisk - created new MD Name:volume2 StorageAccountType:Standard_LRS Size:10 I1001 18:02:48.827] I1001 18:02:48.826630 8886 controllerserver.go:222] create azure disk(volume2) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:02:48.827] I1001 18:02:48.826642 8886 utils.go:119] GRPC response: volume: > > I1001 18:02:48.828] I1001 18:02:48.827427 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:02:48.828] I1001 18:02:48.827460 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume2" name:"snapshot2" I1001 18:02:48.828] I1001 18:02:48.827470 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume2 snapshot2 map[] map[] {} [] 0} I1001 18:02:48.828] I1001 18:02:48.827487 8886 controllerserver.go:463] begin to create snapshot(snapshot2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:02:59.537] I1001 18:02:59.536818 8886 controllerserver.go:476] create snapshot(snapshot2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:02:59.627] I1001 18:02:59.627289 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:02:59.628] I1001 18:02:59.628117 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:02:59.628] I1001 18:02:59.628153 8886 utils.go:113] GRPC request: name:"volume3" capacity_range: volume_capabilities: access_mode: > I1001 18:02:59.727] I1001 18:02:59.726792 8886 controllerserver.go:175] begin to create azure disk(volume3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:02:59.727] I1001 18:02:59.726823 8886 azuredisk.go:244] azureDisk - creating new managed Name:volume3 StorageAccountType:Standard_LRS Size:10 I1001 18:03:00.301] I1001 18:03:00.301196 8886 azuredisk.go:348] azureDisk - created new MD Name:volume3 StorageAccountType:Standard_LRS Size:10 I1001 18:03:00.301] I1001 18:03:00.301246 8886 controllerserver.go:222] create azure disk(volume3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:03:00.302] I1001 18:03:00.301262 8886 utils.go:119] GRPC response: volume: > > I1001 18:03:00.302] I1001 18:03:00.301897 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:03:00.302] I1001 18:03:00.301959 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume3" name:"snapshot3" I1001 18:03:00.303] I1001 18:03:00.301976 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume3 snapshot3 map[] map[] {} [] 0} I1001 18:03:00.303] I1001 18:03:00.302007 8886 controllerserver.go:463] begin to create snapshot(snapshot3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:10.929] I1001 18:03:10.928839 8886 controllerserver.go:476] create snapshot(snapshot3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:11.017] I1001 18:03:11.017056 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:03:11.018] I1001 18:03:11.018201 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:03:11.018] I1001 18:03:11.018251 8886 utils.go:113] GRPC request: name:"volume4" capacity_range: volume_capabilities: access_mode: > I1001 18:03:11.108] I1001 18:03:11.108041 8886 controllerserver.go:175] begin to create azure disk(volume4) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:03:11.108] I1001 18:03:11.108070 8886 azuredisk.go:244] azureDisk - creating new managed Name:volume4 StorageAccountType:Standard_LRS Size:10 I1001 18:03:11.918] I1001 18:03:11.918541 8886 azuredisk.go:348] azureDisk - created new MD Name:volume4 StorageAccountType:Standard_LRS Size:10 I1001 18:03:11.919] I1001 18:03:11.918578 8886 controllerserver.go:222] create azure disk(volume4) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:03:11.919] I1001 18:03:11.918589 8886 utils.go:119] GRPC response: volume: > > I1001 18:03:11.919] I1001 18:03:11.919238 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:03:11.920] I1001 18:03:11.919273 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume4" name:"snapshot4" I1001 18:03:11.920] I1001 18:03:11.919287 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume4 snapshot4 map[] map[] {} [] 0} I1001 18:03:11.920] I1001 18:03:11.919312 8886 controllerserver.go:463] begin to create snapshot(snapshot4) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:22.533] I1001 18:03:22.532971 8886 controllerserver.go:476] create snapshot(snapshot4) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:22.622] I1001 18:03:22.622126 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:03:22.624] I1001 18:03:22.623244 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:03:22.624] I1001 18:03:22.623349 8886 utils.go:113] GRPC request: name:"volume5" capacity_range: volume_capabilities: access_mode: > I1001 18:03:22.706] I1001 18:03:22.705907 8886 controllerserver.go:175] begin to create azure disk(volume5) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:03:22.706] I1001 18:03:22.705983 8886 azuredisk.go:244] azureDisk - creating new managed Name:volume5 StorageAccountType:Standard_LRS Size:10 I1001 18:03:23.415] I1001 18:03:23.415563 8886 azuredisk.go:348] azureDisk - created new MD Name:volume5 StorageAccountType:Standard_LRS Size:10 I1001 18:03:23.416] I1001 18:03:23.415607 8886 controllerserver.go:222] create azure disk(volume5) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:03:23.416] I1001 18:03:23.415619 8886 utils.go:119] GRPC response: volume: > > I1001 18:03:23.417] I1001 18:03:23.416411 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:03:23.417] I1001 18:03:23.416450 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume5" name:"snapshot5" I1001 18:03:23.418] I1001 18:03:23.416466 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume5 snapshot5 map[] map[] {} [] 0} I1001 18:03:23.418] I1001 18:03:23.416513 8886 controllerserver.go:463] begin to create snapshot(snapshot5) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:34.053] I1001 18:03:34.053457 8886 controllerserver.go:476] create snapshot(snapshot5) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:34.142] I1001 18:03:34.141670 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:03:34.142] I1001 18:03:34.142456 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:03:34.142] I1001 18:03:34.142490 8886 utils.go:113] GRPC request: max_entries:2 I1001 18:03:34.143] I1001 18:03:34.142500 8886 controllerserver.go:518] ListSnapshots called with request {2 {} [] 0} I1001 18:03:34.241] I1001 18:03:34.240808 8886 utils.go:119] GRPC response: entries: ready_to_use:true > > entries: ready_to_use:true > > next_token:"2" I1001 18:03:34.241] I1001 18:03:34.241299 8886 utils.go:112] GRPC call: /csi.v1.Controller/ListSnapshots I1001 18:03:34.242] I1001 18:03:34.241326 8886 utils.go:113] GRPC request: starting_token:"2" I1001 18:03:34.242] I1001 18:03:34.241333 8886 controllerserver.go:518] ListSnapshots called with request {0 2 {} [] 0} I1001 18:03:34.340] I1001 18:03:34.338943 8886 utils.go:119] GRPC response: entries: ready_to_use:true > > entries: ready_to_use:true > > entries: ready_to_use:true > > next_token:"2" I1001 18:03:34.340] STEP: cleaning up deleting the snapshots I1001 18:03:34.340] I1001 18:03:34.339604 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:03:34.340] I1001 18:03:34.339633 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot1" I1001 18:03:34.341] I1001 18:03:34.339645 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot1 map[] {} [] 0} I1001 18:03:34.341] I1001 18:03:34.339695 8886 controllerserver.go:503] begin to delete snapshot(snapshot1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:39.742] I1001 18:03:39.742165 8886 controllerserver.go:512] delete snapshot(snapshot1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:39.742] I1001 18:03:39.742199 8886 utils.go:119] GRPC response: I1001 18:03:39.743] I1001 18:03:39.742841 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:03:39.743] I1001 18:03:39.742884 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot2" I1001 18:03:39.744] I1001 18:03:39.742906 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot2 map[] {} [] 0} I1001 18:03:39.744] I1001 18:03:39.742986 8886 controllerserver.go:503] begin to delete snapshot(snapshot2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:45.453] I1001 18:03:45.453056 8886 controllerserver.go:512] delete snapshot(snapshot2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:45.453] I1001 18:03:45.453094 8886 utils.go:119] GRPC response: I1001 18:03:45.454] I1001 18:03:45.453691 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:03:45.454] I1001 18:03:45.453749 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot3" I1001 18:03:45.454] I1001 18:03:45.453775 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot3 map[] {} [] 0} I1001 18:03:45.455] I1001 18:03:45.453838 8886 controllerserver.go:503] begin to delete snapshot(snapshot3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:50.838] I1001 18:03:50.838617 8886 controllerserver.go:512] delete snapshot(snapshot3) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:50.839] I1001 18:03:50.838652 8886 utils.go:119] GRPC response: I1001 18:03:50.839] I1001 18:03:50.839197 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:03:50.839] I1001 18:03:50.839232 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot4" I1001 18:03:50.840] I1001 18:03:50.839246 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot4 map[] {} [] 0} I1001 18:03:50.840] I1001 18:03:50.839298 8886 controllerserver.go:503] begin to delete snapshot(snapshot4) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:03:56.371] I1001 18:03:56.371560 8886 controllerserver.go:512] delete snapshot(snapshot4) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:03:56.372] I1001 18:03:56.371605 8886 utils.go:119] GRPC response: I1001 18:03:56.372] I1001 18:03:56.372232 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:03:56.372] I1001 18:03:56.372264 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot5" I1001 18:03:56.373] I1001 18:03:56.372276 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/snapshot5 map[] {} [] 0} I1001 18:03:56.373] I1001 18:03:56.372386 8886 controllerserver.go:503] begin to delete snapshot(snapshot5) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:04:01.917] I1001 18:04:01.916841 8886 controllerserver.go:512] delete snapshot(snapshot5) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:04:01.917] I1001 18:04:01.916872 8886 utils.go:119] GRPC response: I1001 18:04:01.917] STEP: cleaning up deleting the volumes I1001 18:04:01.918] I1001 18:04:01.917601 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:01.918] I1001 18:04:01.917635 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume1" I1001 18:04:01.918] I1001 18:04:01.917653 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume1) I1001 18:04:07.447] I1001 18:04:07.447033 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume1 I1001 18:04:07.447] I1001 18:04:07.447065 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume1) successfully I1001 18:04:07.448] I1001 18:04:07.447078 8886 utils.go:119] GRPC response: I1001 18:04:07.448] I1001 18:04:07.447658 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:07.448] I1001 18:04:07.447683 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume2" I1001 18:04:07.448] I1001 18:04:07.447697 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume2) I1001 18:04:12.890] I1001 18:04:12.889660 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume2 I1001 18:04:12.890] I1001 18:04:12.889710 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume2) successfully I1001 18:04:12.890] I1001 18:04:12.889720 8886 utils.go:119] GRPC response: I1001 18:04:12.891] I1001 18:04:12.890379 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:12.891] I1001 18:04:12.890417 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume3" I1001 18:04:12.891] I1001 18:04:12.890432 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume3) I1001 18:04:13.291] I1001 18:04:13.291039 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume3 I1001 18:04:13.291] I1001 18:04:13.291067 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume3) successfully I1001 18:04:13.292] I1001 18:04:13.291075 8886 utils.go:119] GRPC response: I1001 18:04:13.292] I1001 18:04:13.291555 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:13.292] I1001 18:04:13.291589 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume4" I1001 18:04:13.293] I1001 18:04:13.291604 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume4) I1001 18:04:18.808] I1001 18:04:18.808391 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume4 I1001 18:04:18.809] I1001 18:04:18.808426 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume4) successfully I1001 18:04:18.809] I1001 18:04:18.808443 8886 utils.go:119] GRPC response: I1001 18:04:18.809] I1001 18:04:18.809105 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:18.810] I1001 18:04:18.809141 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume5" I1001 18:04:18.810] I1001 18:04:18.809160 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume5) I1001 18:04:24.266] I1001 18:04:24.266225 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume5 I1001 18:04:24.267] I1001 18:04:24.266264 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/volume5) successfully I1001 18:04:24.267] I1001 18:04:24.266275 8886 utils.go:119] GRPC response: I1001 18:04:24.267] I1001 18:04:24.267] • [SLOW TEST:120.073 seconds] I1001 18:04:24.268] ListSnapshots [Controller Server] I1001 18:04:24.268] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:04:24.268] should return next token when a limited number of entries are requested I1001 18:04:24.269] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1331 I1001 18:04:24.269] ------------------------------ I1001 18:04:24.269] DeleteSnapshot [Controller Server] I1001 18:04:24.269] should fail when no snapshot id is provided I1001 18:04:24.270] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1439 I1001 18:04:24.270] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:24.270] STEP: creating mount and staging directories I1001 18:04:24.270] I1001 18:04:24.267129 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:24.270] I1001 18:04:24.267155 8886 utils.go:113] GRPC request: I1001 18:04:24.270] I1001 18:04:24.267162 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:24.271] I1001 18:04:24.267167 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:24.271] I1001 18:04:24.267783 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:04:24.271] I1001 18:04:24.267820 8886 utils.go:113] GRPC request: I1001 18:04:24.271] I1001 18:04:24.267831 8886 controllerserver.go:491] DeleteSnapshot called with request { map[] {} [] 0} I1001 18:04:24.271] E1001 18:04:24.267853 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Snapshot ID must be provided I1001 18:04:24.272] • I1001 18:04:24.272] ------------------------------ I1001 18:04:24.272] DeleteSnapshot [Controller Server] I1001 18:04:24.272] should succeed when an invalid snapshot id is used I1001 18:04:24.272] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1455 I1001 18:04:24.272] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:24.272] STEP: creating mount and staging directories I1001 18:04:24.273] I1001 18:04:24.268376 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:24.273] I1001 18:04:24.268407 8886 utils.go:113] GRPC request: I1001 18:04:24.273] I1001 18:04:24.268415 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:24.273] I1001 18:04:24.268421 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:24.273] I1001 18:04:24.268960 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:04:24.274] I1001 18:04:24.268986 8886 utils.go:113] GRPC request: snapshot_id:"reallyfakesnapshotid" I1001 18:04:24.274] I1001 18:04:24.268995 8886 controllerserver.go:491] DeleteSnapshot called with request {reallyfakesnapshotid map[] {} [] 0} I1001 18:04:24.274] I1001 18:04:24.269014 8886 controllerserver.go:503] begin to delete snapshot(reallyfakesnapshotid) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:04:24.397] I1001 18:04:24.397060 8886 controllerserver.go:512] delete snapshot(reallyfakesnapshotid) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:04:24.397] I1001 18:04:24.397098 8886 utils.go:119] GRPC response: I1001 18:04:24.397] • I1001 18:04:24.398] ------------------------------ I1001 18:04:24.398] DeleteSnapshot [Controller Server] I1001 18:04:24.398] should return appropriate values (no optional values added) I1001 18:04:24.398] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1462 I1001 18:04:24.398] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:24.398] STEP: creating mount and staging directories I1001 18:04:24.399] I1001 18:04:24.397621 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:24.399] I1001 18:04:24.397651 8886 utils.go:113] GRPC request: I1001 18:04:24.399] I1001 18:04:24.397659 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:24.399] I1001 18:04:24.397666 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:24.399] STEP: creating a volume I1001 18:04:24.400] I1001 18:04:24.398182 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:04:24.400] I1001 18:04:24.398210 8886 utils.go:113] GRPC request: name:"DeleteSnapshot-volume-1" capacity_range: volume_capabilities: access_mode: > I1001 18:04:24.486] I1001 18:04:24.485966 8886 controllerserver.go:175] begin to create azure disk(DeleteSnapshot-volume-1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:04:24.486] I1001 18:04:24.486008 8886 azuredisk.go:244] azureDisk - creating new managed Name:DeleteSnapshot-volume-1 StorageAccountType:Standard_LRS Size:10 I1001 18:04:25.453] I1001 18:04:25.452796 8886 azuredisk.go:348] azureDisk - created new MD Name:DeleteSnapshot-volume-1 StorageAccountType:Standard_LRS Size:10 I1001 18:04:25.454] I1001 18:04:25.452856 8886 controllerserver.go:222] create azure disk(DeleteSnapshot-volume-1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:04:25.454] I1001 18:04:25.452877 8886 utils.go:119] GRPC response: volume: > > I1001 18:04:25.454] STEP: creating a snapshot I1001 18:04:25.455] I1001 18:04:25.453999 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:04:25.455] I1001 18:04:25.454052 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/DeleteSnapshot-volume-1" name:"DeleteSnapshot-snapshot-1" I1001 18:04:25.455] I1001 18:04:25.454068 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/DeleteSnapshot-volume-1 DeleteSnapshot-snapshot-1 map[] map[] {} [] 0} I1001 18:04:25.456] I1001 18:04:25.454121 8886 controllerserver.go:463] begin to create snapshot(DeleteSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:04:36.035] I1001 18:04:36.034926 8886 controllerserver.go:476] create snapshot(DeleteSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:04:36.129] I1001 18:04:36.129046 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:04:36.129] STEP: cleaning up deleting the snapshot I1001 18:04:36.130] I1001 18:04:36.129855 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:04:36.130] I1001 18:04:36.129886 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/DeleteSnapshot-snapshot-1" I1001 18:04:36.131] I1001 18:04:36.129900 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/DeleteSnapshot-snapshot-1 map[] {} [] 0} I1001 18:04:36.131] I1001 18:04:36.129994 8886 controllerserver.go:503] begin to delete snapshot(DeleteSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:04:41.617] I1001 18:04:41.617327 8886 controllerserver.go:512] delete snapshot(DeleteSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:04:41.618] I1001 18:04:41.617356 8886 utils.go:119] GRPC response: I1001 18:04:41.618] STEP: cleaning up deleting the volume I1001 18:04:41.618] I1001 18:04:41.618234 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:41.619] I1001 18:04:41.618275 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/DeleteSnapshot-volume-1" I1001 18:04:41.619] I1001 18:04:41.618288 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/DeleteSnapshot-volume-1) I1001 18:04:47.089] I1001 18:04:47.089487 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/DeleteSnapshot-volume-1 I1001 18:04:47.090] I1001 18:04:47.089527 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/DeleteSnapshot-volume-1) successfully I1001 18:04:47.090] I1001 18:04:47.089541 8886 utils.go:119] GRPC response: I1001 18:04:47.090] I1001 18:04:47.091] • [SLOW TEST:22.693 seconds] I1001 18:04:47.091] DeleteSnapshot [Controller Server] I1001 18:04:47.091] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:04:47.091] should return appropriate values (no optional values added) I1001 18:04:47.092] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1462 I1001 18:04:47.092] ------------------------------ I1001 18:04:47.092] Controller Service ControllerGetCapabilities I1001 18:04:47.092] should return appropriate capabilities I1001 18:04:47.093] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:107 I1001 18:04:47.093] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:47.093] STEP: creating mount and staging directories I1001 18:04:47.093] I1001 18:04:47.090391 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:47.094] I1001 18:04:47.090436 8886 utils.go:113] GRPC request: I1001 18:04:47.094] I1001 18:04:47.090449 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:47.094] I1001 18:04:47.090455 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:47.095] STEP: checking successful response I1001 18:04:47.095] • I1001 18:04:47.095] ------------------------------ I1001 18:04:47.095] Controller Service GetCapacity I1001 18:04:47.095] should return capacity (no optional values added) I1001 18:04:47.096] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:143 I1001 18:04:47.096] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:47.096] STEP: creating mount and staging directories I1001 18:04:47.097] I1001 18:04:47.091259 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:47.097] I1001 18:04:47.091294 8886 utils.go:113] GRPC request: I1001 18:04:47.097] I1001 18:04:47.091303 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:47.097] I1001 18:04:47.091309 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:47.097] I1001 18:04:47.098] S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds] I1001 18:04:47.098] Controller Service I1001 18:04:47.098] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:04:47.098] GetCapacity I1001 18:04:47.098] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:136 I1001 18:04:47.098] should return capacity (no optional values added) [BeforeEach] I1001 18:04:47.099] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:143 I1001 18:04:47.099] I1001 18:04:47.099] GetCapacity not supported I1001 18:04:47.099] I1001 18:04:47.099] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:139 I1001 18:04:47.099] ------------------------------ I1001 18:04:47.100] Controller Service ListVolumes I1001 18:04:47.100] should return appropriate values (no optional values added) I1001 18:04:47.100] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:161 I1001 18:04:47.100] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:47.100] STEP: creating mount and staging directories I1001 18:04:47.100] I1001 18:04:47.092515 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:47.101] I1001 18:04:47.092549 8886 utils.go:113] GRPC request: I1001 18:04:47.101] I1001 18:04:47.092558 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:47.101] I1001 18:04:47.092565 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:47.101] I1001 18:04:47.101] S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds] I1001 18:04:47.101] Controller Service I1001 18:04:47.102] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:04:47.102] ListVolumes I1001 18:04:47.102] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:154 I1001 18:04:47.102] should return appropriate values (no optional values added) [BeforeEach] I1001 18:04:47.102] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:161 I1001 18:04:47.102] I1001 18:04:47.103] ListVolumes not supported I1001 18:04:47.103] I1001 18:04:47.103] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:157 I1001 18:04:47.103] ------------------------------ I1001 18:04:47.103] Controller Service CreateVolume I1001 18:04:47.103] should fail when no name is provided I1001 18:04:47.104] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:186 I1001 18:04:47.104] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:47.104] STEP: creating mount and staging directories I1001 18:04:47.104] I1001 18:04:47.093642 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:47.104] I1001 18:04:47.093669 8886 utils.go:113] GRPC request: I1001 18:04:47.104] I1001 18:04:47.093675 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:47.105] I1001 18:04:47.093679 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:47.105] I1001 18:04:47.094206 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:04:47.105] I1001 18:04:47.094243 8886 utils.go:113] GRPC request: I1001 18:04:47.105] E1001 18:04:47.094254 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = CreateVolume Name must be provided I1001 18:04:47.105] • I1001 18:04:47.105] ------------------------------ I1001 18:04:47.106] Controller Service CreateVolume I1001 18:04:47.106] should fail when no volume capabilities are provided I1001 18:04:47.106] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:202 I1001 18:04:47.106] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:47.106] STEP: creating mount and staging directories I1001 18:04:47.106] I1001 18:04:47.094702 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:47.106] I1001 18:04:47.094730 8886 utils.go:113] GRPC request: I1001 18:04:47.107] I1001 18:04:47.094738 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:47.107] I1001 18:04:47.094744 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:47.107] I1001 18:04:47.095484 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:04:47.107] I1001 18:04:47.095511 8886 utils.go:113] GRPC request: name:"sanity-controller-create-no-volume-capabilities-7632817E-817F5FAA" I1001 18:04:47.108] E1001 18:04:47.095520 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = CreateVolume Volume capabilities must be provided I1001 18:04:47.108] • I1001 18:04:47.108] ------------------------------ I1001 18:04:47.108] Controller Service CreateVolume I1001 18:04:47.108] should return appropriate values SingleNodeWriter NoCapacity Type:Mount I1001 18:04:47.108] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:220 I1001 18:04:47.109] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:47.109] STEP: creating mount and staging directories I1001 18:04:47.109] I1001 18:04:47.096047 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:47.109] I1001 18:04:47.096080 8886 utils.go:113] GRPC request: I1001 18:04:47.109] I1001 18:04:47.096087 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:47.109] I1001 18:04:47.096091 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:47.110] STEP: creating a volume I1001 18:04:47.110] I1001 18:04:47.096708 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:04:47.110] I1001 18:04:47.096747 8886 utils.go:113] GRPC request: name:"sanity-controller-create-single-no-capacity-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:04:47.179] I1001 18:04:47.179085 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-create-single-no-capacity-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) I1001 18:04:47.179] I1001 18:04:47.179120 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-create-single-no-capacity-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:04:47.855] I1001 18:04:47.855482 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-create-single-no-capacity-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:04:47.856] I1001 18:04:47.855536 8886 controllerserver.go:222] create azure disk(sanity-controller-create-single-no-capacity-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) successfully I1001 18:04:47.857] I1001 18:04:47.855549 8886 utils.go:119] GRPC response: volume: > > I1001 18:04:47.857] STEP: cleaning up deleting the volume I1001 18:04:47.857] I1001 18:04:47.856630 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:47.858] I1001 18:04:47.856672 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-no-capacity-7632817E-817F5FAA" I1001 18:04:47.858] I1001 18:04:47.856687 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-no-capacity-7632817E-817F5FAA) I1001 18:04:53.271] I1001 18:04:53.270619 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-no-capacity-7632817E-817F5FAA I1001 18:04:53.271] I1001 18:04:53.270669 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-no-capacity-7632817E-817F5FAA) successfully I1001 18:04:53.271] I1001 18:04:53.270679 8886 utils.go:119] GRPC response: I1001 18:04:53.272] I1001 18:04:53.272] • [SLOW TEST:6.175 seconds] I1001 18:04:53.272] Controller Service I1001 18:04:53.272] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:04:53.273] CreateVolume I1001 18:04:53.273] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:179 I1001 18:04:53.273] should return appropriate values SingleNodeWriter NoCapacity Type:Mount I1001 18:04:53.273] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:220 I1001 18:04:53.273] ------------------------------ I1001 18:04:53.273] Controller Service CreateVolume I1001 18:04:53.274] should return appropriate values SingleNodeWriter WithCapacity 1Gi Type:Mount I1001 18:04:53.274] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:262 I1001 18:04:53.274] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:53.274] STEP: creating mount and staging directories I1001 18:04:53.275] I1001 18:04:53.271399 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:53.275] I1001 18:04:53.271426 8886 utils.go:113] GRPC request: I1001 18:04:53.275] I1001 18:04:53.271435 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:53.275] I1001 18:04:53.271442 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:53.275] STEP: creating a volume I1001 18:04:53.276] I1001 18:04:53.272201 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:04:53.276] I1001 18:04:53.272244 8886 utils.go:113] GRPC request: name:"sanity-controller-create-single-with-capacity-7632817E-817F5FAA" capacity_range: volume_capabilities: access_mode: > I1001 18:04:53.384] I1001 18:04:53.384443 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-create-single-with-capacity-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:04:53.385] I1001 18:04:53.384489 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-create-single-with-capacity-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:04:54.034] I1001 18:04:54.034100 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-create-single-with-capacity-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:04:54.034] I1001 18:04:54.034133 8886 controllerserver.go:222] create azure disk(sanity-controller-create-single-with-capacity-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:04:54.035] I1001 18:04:54.034146 8886 utils.go:119] GRPC response: volume: > > I1001 18:04:54.035] STEP: cleaning up deleting the volume I1001 18:04:54.035] I1001 18:04:54.034845 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:04:54.035] I1001 18:04:54.034872 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-with-capacity-7632817E-817F5FAA" I1001 18:04:54.036] I1001 18:04:54.034885 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-with-capacity-7632817E-817F5FAA) I1001 18:04:59.445] I1001 18:04:59.445391 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-with-capacity-7632817E-817F5FAA I1001 18:04:59.446] I1001 18:04:59.445428 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-single-with-capacity-7632817E-817F5FAA) successfully I1001 18:04:59.446] I1001 18:04:59.445439 8886 utils.go:119] GRPC response: I1001 18:04:59.446] I1001 18:04:59.447] • [SLOW TEST:6.175 seconds] I1001 18:04:59.447] Controller Service I1001 18:04:59.447] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:04:59.447] CreateVolume I1001 18:04:59.447] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:179 I1001 18:04:59.448] should return appropriate values SingleNodeWriter WithCapacity 1Gi Type:Mount I1001 18:04:59.448] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:262 I1001 18:04:59.448] ------------------------------ I1001 18:04:59.448] Controller Service CreateVolume I1001 18:04:59.448] should not fail when requesting to create a volume with already existing name and same capacity. I1001 18:04:59.449] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:311 I1001 18:04:59.449] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:04:59.449] STEP: creating mount and staging directories I1001 18:04:59.449] I1001 18:04:59.446194 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:04:59.449] I1001 18:04:59.446235 8886 utils.go:113] GRPC request: I1001 18:04:59.450] I1001 18:04:59.446245 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:04:59.450] I1001 18:04:59.446251 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:04:59.450] STEP: creating a volume I1001 18:04:59.450] I1001 18:04:59.446961 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:04:59.451] I1001 18:04:59.446991 8886 utils.go:113] GRPC request: name:"sanity-controller-create-twice-7632817E-817F5FAA" capacity_range: volume_capabilities: access_mode: > I1001 18:04:59.544] I1001 18:04:59.544286 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-create-twice-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:04:59.544] I1001 18:04:59.544315 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-create-twice-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:05:00.114] I1001 18:05:00.114645 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-create-twice-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:05:00.115] I1001 18:05:00.114693 8886 controllerserver.go:222] create azure disk(sanity-controller-create-twice-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:05:00.115] I1001 18:05:00.114703 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:00.116] I1001 18:05:00.115281 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:00.116] I1001 18:05:00.115315 8886 utils.go:113] GRPC request: name:"sanity-controller-create-twice-7632817E-817F5FAA" capacity_range: volume_capabilities: access_mode: > I1001 18:05:00.207] I1001 18:05:00.207268 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-create-twice-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:05:00.207] I1001 18:05:00.207309 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-create-twice-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:05:00.703] I1001 18:05:00.703059 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-create-twice-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:05:00.703] I1001 18:05:00.703108 8886 controllerserver.go:222] create azure disk(sanity-controller-create-twice-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:05:00.704] I1001 18:05:00.703119 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:00.704] STEP: cleaning up deleting the volume I1001 18:05:00.704] I1001 18:05:00.703813 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:00.705] I1001 18:05:00.703846 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-7632817E-817F5FAA" I1001 18:05:00.705] I1001 18:05:00.703860 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-7632817E-817F5FAA) I1001 18:05:06.134] I1001 18:05:06.133720 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-7632817E-817F5FAA I1001 18:05:06.134] I1001 18:05:06.133749 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-7632817E-817F5FAA) successfully I1001 18:05:06.134] I1001 18:05:06.133757 8886 utils.go:119] GRPC response: I1001 18:05:06.134] I1001 18:05:06.135] • [SLOW TEST:6.688 seconds] I1001 18:05:06.135] Controller Service I1001 18:05:06.135] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:06.135] CreateVolume I1001 18:05:06.135] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:179 I1001 18:05:06.135] should not fail when requesting to create a volume with already existing name and same capacity. I1001 18:05:06.135] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:311 I1001 18:05:06.136] ------------------------------ I1001 18:05:06.136] Controller Service CreateVolume I1001 18:05:06.136] should fail when requesting to create a volume with already existing name and different capacity. I1001 18:05:06.136] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:385 I1001 18:05:06.136] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:06.136] STEP: creating mount and staging directories I1001 18:05:06.136] I1001 18:05:06.134358 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:06.137] I1001 18:05:06.134413 8886 utils.go:113] GRPC request: I1001 18:05:06.137] I1001 18:05:06.134437 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:06.137] I1001 18:05:06.134442 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:06.137] STEP: creating a volume I1001 18:05:06.137] I1001 18:05:06.134875 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:06.137] I1001 18:05:06.134899 8886 utils.go:113] GRPC request: name:"sanity-controller-create-twice-different-7632817E-817F5FAA" capacity_range: volume_capabilities: access_mode: > I1001 18:05:06.216] I1001 18:05:06.216604 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-create-twice-different-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:05:06.217] I1001 18:05:06.216628 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-create-twice-different-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:05:06.979] I1001 18:05:06.979167 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-create-twice-different-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:10 I1001 18:05:06.980] I1001 18:05:06.979207 8886 controllerserver.go:222] create azure disk(sanity-controller-create-twice-different-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:05:06.980] I1001 18:05:06.979217 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:06.980] I1001 18:05:06.979990 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:06.981] I1001 18:05:06.980025 8886 utils.go:113] GRPC request: name:"sanity-controller-create-twice-different-7632817E-817F5FAA" capacity_range: volume_capabilities: access_mode: > I1001 18:05:07.082] E1001 18:05:07.081964 8886 utils.go:117] GRPC error: rpc error: code = AlreadyExists desc = the request volume already exists, but its capacity(10) is different from (20) I1001 18:05:07.082] STEP: cleaning up deleting the volume I1001 18:05:07.082] I1001 18:05:07.082565 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:07.083] I1001 18:05:07.082597 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-different-7632817E-817F5FAA" I1001 18:05:07.083] I1001 18:05:07.082622 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-different-7632817E-817F5FAA) I1001 18:05:12.563] I1001 18:05:12.562500 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-different-7632817E-817F5FAA I1001 18:05:12.563] I1001 18:05:12.562555 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-twice-different-7632817E-817F5FAA) successfully I1001 18:05:12.563] I1001 18:05:12.562564 8886 utils.go:119] GRPC response: I1001 18:05:12.564] I1001 18:05:12.564] • [SLOW TEST:6.430 seconds] I1001 18:05:12.564] Controller Service I1001 18:05:12.564] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:12.564] CreateVolume I1001 18:05:12.565] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:179 I1001 18:05:12.565] should fail when requesting to create a volume with already existing name and different capacity. I1001 18:05:12.565] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:385 I1001 18:05:12.566] ------------------------------ I1001 18:05:12.566] Controller Service CreateVolume I1001 18:05:12.566] should not fail when creating volume with maximum-length name I1001 18:05:12.566] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:460 I1001 18:05:12.567] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:12.567] STEP: creating mount and staging directories I1001 18:05:12.567] I1001 18:05:12.564678 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:12.567] I1001 18:05:12.564699 8886 utils.go:113] GRPC request: I1001 18:05:12.567] I1001 18:05:12.564708 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:12.568] I1001 18:05:12.564740 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:12.568] STEP: creating a volume I1001 18:05:12.568] I1001 18:05:12.565765 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:12.569] I1001 18:05:12.565816 8886 utils.go:113] GRPC request: name:"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" capacity_range: volume_capabilities: access_mode: > I1001 18:05:12.569] W1001 18:05:12.565832 8886 azuredisk.go:368] since the maximum volume name length is 80, so it is truncated as ("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa") I1001 18:05:12.650] I1001 18:05:12.649918 8886 controllerserver.go:175] begin to create azure disk(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:05:12.650] I1001 18:05:12.649980 8886 azuredisk.go:244] azureDisk - creating new managed Name:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa StorageAccountType:Standard_LRS Size:10 I1001 18:05:13.303] I1001 18:05:13.302762 8886 azuredisk.go:348] azureDisk - created new MD Name:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa StorageAccountType:Standard_LRS Size:10 I1001 18:05:13.303] I1001 18:05:13.302823 8886 controllerserver.go:222] create azure disk(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:05:13.304] I1001 18:05:13.302835 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:13.304] STEP: cleaning up deleting the volume I1001 18:05:13.304] I1001 18:05:13.303597 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:13.304] I1001 18:05:13.303632 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" I1001 18:05:13.305] I1001 18:05:13.303645 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) I1001 18:05:18.816] I1001 18:05:18.815792 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa I1001 18:05:18.816] I1001 18:05:18.815838 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) successfully I1001 18:05:18.817] I1001 18:05:18.815857 8886 utils.go:119] GRPC response: I1001 18:05:18.817] I1001 18:05:18.817] • [SLOW TEST:6.252 seconds] I1001 18:05:18.817] Controller Service I1001 18:05:18.818] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:18.818] CreateVolume I1001 18:05:18.818] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:179 I1001 18:05:18.819] should not fail when creating volume with maximum-length name I1001 18:05:18.819] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:460 I1001 18:05:18.819] ------------------------------ I1001 18:05:18.819] Controller Service DeleteVolume I1001 18:05:18.819] should fail when no volume id is provided I1001 18:05:18.820] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:519 I1001 18:05:18.820] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:18.820] STEP: creating mount and staging directories I1001 18:05:18.820] I1001 18:05:18.816785 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:18.821] I1001 18:05:18.816817 8886 utils.go:113] GRPC request: I1001 18:05:18.821] I1001 18:05:18.816828 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:18.821] I1001 18:05:18.816834 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:18.822] I1001 18:05:18.817396 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:18.822] I1001 18:05:18.817431 8886 utils.go:113] GRPC request: I1001 18:05:18.822] E1001 18:05:18.817440 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID missing in request I1001 18:05:18.822] • I1001 18:05:18.822] ------------------------------ I1001 18:05:18.823] Controller Service DeleteVolume I1001 18:05:18.823] should succeed when an invalid volume id is used I1001 18:05:18.823] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:534 I1001 18:05:18.823] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:18.824] STEP: creating mount and staging directories I1001 18:05:18.824] I1001 18:05:18.818117 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:18.824] I1001 18:05:18.818168 8886 utils.go:113] GRPC request: I1001 18:05:18.824] I1001 18:05:18.818179 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:18.825] I1001 18:05:18.818185 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:18.825] I1001 18:05:18.818653 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:18.825] I1001 18:05:18.818683 8886 utils.go:113] GRPC request: volume_id:"reallyfakevolumeid" I1001 18:05:18.825] E1001 18:05:18.818698 8886 controllerserver.go:273] validateDiskURI(reallyfakevolumeid) in DeleteVolume failed with error: Inavlid DiskURI: reallyfakevolumeid, correct format: [/subscriptions/{sub-id}/resourcegroups/{group-name}/providers/microsoft.compute/disks/{disk-id}] I1001 18:05:18.826] I1001 18:05:18.818705 8886 utils.go:119] GRPC response: I1001 18:05:18.826] • I1001 18:05:18.826] ------------------------------ I1001 18:05:18.826] Controller Service DeleteVolume I1001 18:05:18.827] should return appropriate values (no optional values added) I1001 18:05:18.827] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:546 I1001 18:05:18.827] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:18.827] STEP: creating mount and staging directories I1001 18:05:18.827] I1001 18:05:18.819174 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:18.827] I1001 18:05:18.819216 8886 utils.go:113] GRPC request: I1001 18:05:18.828] I1001 18:05:18.819226 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:18.828] I1001 18:05:18.819232 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:18.828] STEP: creating a volume I1001 18:05:18.828] I1001 18:05:18.819891 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:18.829] I1001 18:05:18.819925 8886 utils.go:113] GRPC request: name:"sanity-controller-create-appropriate-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:05:18.902] I1001 18:05:18.902302 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-create-appropriate-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) I1001 18:05:18.903] I1001 18:05:18.902332 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-create-appropriate-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:19.582] I1001 18:05:19.582121 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-create-appropriate-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:19.583] I1001 18:05:19.582210 8886 controllerserver.go:222] create azure disk(sanity-controller-create-appropriate-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) successfully I1001 18:05:19.583] I1001 18:05:19.582226 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:19.583] STEP: deleting a volume I1001 18:05:19.583] I1001 18:05:19.583073 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:19.584] I1001 18:05:19.583110 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-appropriate-7632817E-817F5FAA" I1001 18:05:19.584] I1001 18:05:19.583127 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-appropriate-7632817E-817F5FAA) I1001 18:05:19.941] I1001 18:05:19.941047 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-appropriate-7632817E-817F5FAA I1001 18:05:19.941] I1001 18:05:19.941079 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-create-appropriate-7632817E-817F5FAA) successfully I1001 18:05:19.942] I1001 18:05:19.941087 8886 utils.go:119] GRPC response: I1001 18:05:19.942] • I1001 18:05:19.942] ------------------------------ I1001 18:05:19.942] Controller Service ValidateVolumeCapabilities I1001 18:05:19.943] should fail when no volume id is provided I1001 18:05:19.943] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:592 I1001 18:05:19.943] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:19.943] STEP: creating mount and staging directories I1001 18:05:19.944] I1001 18:05:19.941885 8886 utils.go:112] GRPC call: /csi.v1.Controller/ValidateVolumeCapabilities I1001 18:05:19.944] I1001 18:05:19.941924 8886 utils.go:113] GRPC request: I1001 18:05:19.944] E1001 18:05:19.941936 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID missing in request I1001 18:05:19.944] • I1001 18:05:19.944] ------------------------------ I1001 18:05:19.944] Controller Service ValidateVolumeCapabilities I1001 18:05:19.945] should fail when no volume capabilities are provided I1001 18:05:19.945] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:604 I1001 18:05:19.945] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:19.945] STEP: creating mount and staging directories I1001 18:05:19.945] I1001 18:05:19.942528 8886 utils.go:112] GRPC call: /csi.v1.Controller/ValidateVolumeCapabilities I1001 18:05:19.946] I1001 18:05:19.942562 8886 utils.go:113] GRPC request: volume_id:"id" I1001 18:05:19.946] E1001 18:05:19.942572 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capabilities missing in request I1001 18:05:19.946] • I1001 18:05:19.946] ------------------------------ I1001 18:05:19.946] Controller Service ValidateVolumeCapabilities I1001 18:05:19.946] should return appropriate values (no optional values added) I1001 18:05:19.947] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:618 I1001 18:05:19.947] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:19.947] STEP: creating mount and staging directories I1001 18:05:19.947] STEP: creating a single node writer volume I1001 18:05:19.947] I1001 18:05:19.943122 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:19.948] I1001 18:05:19.943154 8886 utils.go:113] GRPC request: name:"sanity-controller-validate-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:05:20.025] I1001 18:05:20.025057 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-validate-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) I1001 18:05:20.025] I1001 18:05:20.025105 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-validate-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:20.690] I1001 18:05:20.690350 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-validate-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:20.691] I1001 18:05:20.690389 8886 controllerserver.go:222] create azure disk(sanity-controller-validate-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) successfully I1001 18:05:20.691] I1001 18:05:20.690401 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:20.691] STEP: validating volume capabilities I1001 18:05:20.692] I1001 18:05:20.691149 8886 utils.go:112] GRPC call: /csi.v1.Controller/ValidateVolumeCapabilities I1001 18:05:20.692] I1001 18:05:20.691186 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-validate-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:05:20.788] I1001 18:05:20.787860 8886 utils.go:119] GRPC response: I1001 18:05:20.788] STEP: cleaning up deleting the volume I1001 18:05:20.788] I1001 18:05:20.788524 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:20.789] I1001 18:05:20.788553 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-validate-7632817E-817F5FAA" I1001 18:05:20.789] I1001 18:05:20.788568 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-validate-7632817E-817F5FAA) I1001 18:05:26.287] I1001 18:05:26.287497 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-validate-7632817E-817F5FAA I1001 18:05:26.288] I1001 18:05:26.287534 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-validate-7632817E-817F5FAA) successfully I1001 18:05:26.288] I1001 18:05:26.287550 8886 utils.go:119] GRPC response: I1001 18:05:26.288] I1001 18:05:26.289] • [SLOW TEST:6.345 seconds] I1001 18:05:26.289] Controller Service I1001 18:05:26.289] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:26.290] ValidateVolumeCapabilities I1001 18:05:26.290] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:591 I1001 18:05:26.290] should return appropriate values (no optional values added) I1001 18:05:26.290] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:618 I1001 18:05:26.291] ------------------------------ I1001 18:05:26.291] Controller Service ValidateVolumeCapabilities I1001 18:05:26.291] should fail when the requested volume does not exist I1001 18:05:26.291] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:687 I1001 18:05:26.292] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:26.292] STEP: creating mount and staging directories I1001 18:05:26.292] I1001 18:05:26.288458 8886 utils.go:112] GRPC call: /csi.v1.Controller/ValidateVolumeCapabilities I1001 18:05:26.292] I1001 18:05:26.288485 8886 utils.go:113] GRPC request: volume_id:"some-vol-id" volume_capabilities: access_mode: > I1001 18:05:26.293] E1001 18:05:26.288504 8886 utils.go:117] GRPC error: rpc error: code = NotFound desc = Volume not found, failed with error: could not get disk name from some-vol-id, correct format: .*/subscriptions/(?:.*)/resourceGroups/(?:.*)/providers/Microsoft.Compute/disks/(.+) I1001 18:05:26.293] • I1001 18:05:26.293] ------------------------------ I1001 18:05:26.294] Controller Service ControllerPublishVolume I1001 18:05:26.294] should fail when no volume id is provided I1001 18:05:26.294] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:720 I1001 18:05:26.294] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:26.294] STEP: creating mount and staging directories I1001 18:05:26.295] I1001 18:05:26.289188 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:26.295] I1001 18:05:26.289224 8886 utils.go:113] GRPC request: I1001 18:05:26.295] I1001 18:05:26.289236 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:26.295] I1001 18:05:26.289243 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:26.295] I1001 18:05:26.290117 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:26.296] I1001 18:05:26.290155 8886 utils.go:113] GRPC request: I1001 18:05:26.296] I1001 18:05:26.290168 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId: NodeId: VolumeCapability: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:26.296] E1001 18:05:26.290194 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID not provided I1001 18:05:26.296] • I1001 18:05:26.297] ------------------------------ I1001 18:05:26.297] Controller Service ControllerPublishVolume I1001 18:05:26.297] should fail when no node id is provided I1001 18:05:26.297] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:735 I1001 18:05:26.297] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:26.298] STEP: creating mount and staging directories I1001 18:05:26.298] I1001 18:05:26.290750 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:26.298] I1001 18:05:26.290775 8886 utils.go:113] GRPC request: I1001 18:05:26.298] I1001 18:05:26.290786 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:26.298] I1001 18:05:26.290792 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:26.299] I1001 18:05:26.291235 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:26.299] I1001 18:05:26.291261 8886 utils.go:113] GRPC request: volume_id:"id" I1001 18:05:26.299] I1001 18:05:26.291269 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId:id NodeId: VolumeCapability: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:26.299] E1001 18:05:26.291290 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capability not provided I1001 18:05:26.300] • I1001 18:05:26.300] ------------------------------ I1001 18:05:26.300] Controller Service ControllerPublishVolume I1001 18:05:26.300] should fail when no volume capability is provided I1001 18:05:26.300] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:751 I1001 18:05:26.301] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:26.301] STEP: creating mount and staging directories I1001 18:05:26.301] I1001 18:05:26.291747 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:26.301] I1001 18:05:26.291769 8886 utils.go:113] GRPC request: I1001 18:05:26.301] I1001 18:05:26.291777 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:26.302] I1001 18:05:26.291783 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:26.302] I1001 18:05:26.292292 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:26.302] I1001 18:05:26.292318 8886 utils.go:113] GRPC request: volume_id:"id" node_id:"fakenode" I1001 18:05:26.302] I1001 18:05:26.292329 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId:id NodeId:fakenode VolumeCapability: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:26.303] E1001 18:05:26.292354 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capability not provided I1001 18:05:26.303] • I1001 18:05:26.303] ------------------------------ I1001 18:05:26.303] Controller Service ControllerPublishVolume I1001 18:05:26.303] should return appropriate values (no optional values added) I1001 18:05:26.303] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:768 I1001 18:05:26.304] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:26.304] STEP: creating mount and staging directories I1001 18:05:26.304] I1001 18:05:26.292817 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:26.304] I1001 18:05:26.292848 8886 utils.go:113] GRPC request: I1001 18:05:26.304] I1001 18:05:26.292857 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:26.305] I1001 18:05:26.292868 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:26.305] STEP: creating a single node writer volume I1001 18:05:26.305] I1001 18:05:26.293441 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:26.305] I1001 18:05:26.293465 8886 utils.go:113] GRPC request: name:"sanity-controller-publish-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:05:26.382] I1001 18:05:26.382566 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-publish-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) I1001 18:05:26.383] I1001 18:05:26.382607 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-publish-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:27.120] I1001 18:05:27.120546 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-publish-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:27.121] I1001 18:05:27.120575 8886 controllerserver.go:222] create azure disk(sanity-controller-publish-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) successfully I1001 18:05:27.121] I1001 18:05:27.120585 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:27.121] STEP: getting a node id I1001 18:05:27.122] I1001 18:05:27.121174 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetInfo I1001 18:05:27.122] I1001 18:05:27.121200 8886 utils.go:113] GRPC request: I1001 18:05:27.122] I1001 18:05:27.121208 8886 nodeserver.go:281] Using default NodeGetInfo I1001 18:05:27.210] I1001 18:05:27.210119 8886 azure_wrap.go:222] Virtual machine "CSINode" not found with message: "compute.VirtualMachinesClient#Get: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code=\"ResourceNotFound\" Message=\"The Resource 'Microsoft.Compute/virtualMachines/CSINode' under resource group 'azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc' was not found.\"" I1001 18:05:27.210] E1001 18:05:27.210154 8886 azure_standard.go:392] as.GetInstanceTypeByNodeName(CSINode) failed: as.getVirtualMachine(CSINode) err=instance not found I1001 18:05:27.211] W1001 18:05:27.210171 8886 nodeserver.go:290] Failed to get instance type from Azure cloud provider, nodeName: CSINode, error: instance not found I1001 18:05:27.323] I1001 18:05:27.323706 8886 utils.go:119] GRPC response: node_id:"CSINode" max_volumes_per_node:16 I1001 18:05:27.324] STEP: calling controllerpublish on that volume I1001 18:05:27.324] I1001 18:05:27.324276 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:27.324] I1001 18:05:27.324300 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA" node_id:"CSINode" volume_capability: access_mode: > I1001 18:05:27.325] I1001 18:05:27.324329 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId:/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA NodeId:CSINode VolumeCapability:mount:<> access_mode: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:27.425] I1001 18:05:27.424731 8886 controllerserver.go:326] GetDiskLun returned: . Initiating attaching volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA" to node "CSINode". I1001 18:05:27.506] I1001 18:05:27.505731 8886 azure_wrap.go:222] Virtual machine "CSINode" not found with message: "compute.VirtualMachinesClient#Get: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code=\"ResourceNotFound\" Message=\"The Resource 'Microsoft.Compute/virtualMachines/CSINode' under resource group 'azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc' was not found.\"" I1001 18:05:27.506] E1001 18:05:27.505793 8886 azure_controller_common.go:193] error of getting data disks for node "CSINode": instance not found I1001 18:05:27.507] E1001 18:05:27.505810 8886 utils.go:117] GRPC error: rpc error: code = NotFound desc = failed to get azure instance id for node "CSINode" (instance not found) I1001 18:05:27.507] cleanup: deleting sanity-controller-publish-7632817E-817F5FAA = /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA I1001 18:05:27.507] I1001 18:05:27.507125 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeUnpublishVolume I1001 18:05:27.508] I1001 18:05:27.507153 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA" target_path:"/tmp/csi" I1001 18:05:27.508] I1001 18:05:27.507169 8886 nodeserver.go:260] NodeUnpublishVolume: unmounting volume /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA on /tmp/csi I1001 18:05:27.508] I1001 18:05:27.507183 8886 mount_linux.go:209] Unmounting /tmp/csi I1001 18:05:27.512] E1001 18:05:27.512646 8886 utils.go:117] GRPC error: rpc error: code = Internal desc = Unmount failed: exit status 32 I1001 18:05:27.513] Unmounting arguments: /tmp/csi I1001 18:05:27.513] Output: umount: /tmp/csi: not mounted I1001 18:05:27.513] I1001 18:05:27.513] cleanup: warning: NodeUnpublishVolume: rpc error: code = Internal desc = Unmount failed: exit status 32 I1001 18:05:27.514] Unmounting arguments: /tmp/csi I1001 18:05:27.514] Output: umount: /tmp/csi: not mounted I1001 18:05:27.514] I1001 18:05:27.514] I1001 18:05:27.513165 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:27.515] I1001 18:05:27.513195 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA" I1001 18:05:27.515] I1001 18:05:27.513205 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA) I1001 18:05:32.960] I1001 18:05:32.959937 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA I1001 18:05:32.960] I1001 18:05:32.959972 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-publish-7632817E-817F5FAA) successfully I1001 18:05:32.961] I1001 18:05:32.959982 8886 utils.go:119] GRPC response: I1001 18:05:32.962] I1001 18:05:32.962] • Failure [6.668 seconds] I1001 18:05:32.962] Controller Service I1001 18:05:32.962] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:32.963] ControllerPublishVolume I1001 18:05:32.963] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:713 I1001 18:05:32.963] should return appropriate values (no optional values added) [It] I1001 18:05:32.963] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:768 I1001 18:05:32.964] I1001 18:05:32.964] Unexpected error: I1001 18:05:32.964] <*status.statusError | 0xc0004e1360>: { I1001 18:05:32.964] Code: 5, I1001 18:05:32.964] Message: "failed to get azure instance id for node \"CSINode\" (instance not found)", I1001 18:05:32.965] Details: nil, I1001 18:05:32.965] XXX_NoUnkeyedLiteral: {}, I1001 18:05:32.965] XXX_unrecognized: nil, I1001 18:05:32.965] XXX_sizecache: 0, I1001 18:05:32.966] } I1001 18:05:32.966] rpc error: code = NotFound desc = failed to get azure instance id for node "CSINode" (instance not found) I1001 18:05:32.966] occurred I1001 18:05:32.966] I1001 18:05:32.967] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:826 I1001 18:05:32.967] ------------------------------ I1001 18:05:32.967] Controller Service ControllerPublishVolume I1001 18:05:32.967] should fail when the volume does not exist I1001 18:05:32.967] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:857 I1001 18:05:32.968] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:32.968] STEP: creating mount and staging directories I1001 18:05:32.968] I1001 18:05:32.960694 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:32.968] I1001 18:05:32.960730 8886 utils.go:113] GRPC request: I1001 18:05:32.969] I1001 18:05:32.960738 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:32.969] I1001 18:05:32.960743 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:32.969] STEP: calling controller publish on a non-existent volume I1001 18:05:32.970] I1001 18:05:32.962799 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:32.970] I1001 18:05:32.962850 8886 utils.go:113] GRPC request: volume_id:"some-vol-id" node_id:"some-node-id" volume_capability: access_mode: > I1001 18:05:32.970] I1001 18:05:32.962917 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId:some-vol-id NodeId:some-node-id VolumeCapability:mount:<> access_mode: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:32.971] E1001 18:05:32.962981 8886 utils.go:117] GRPC error: rpc error: code = NotFound desc = Volume not found, failed with error: could not get disk name from some-vol-id, correct format: .*/subscriptions/(?:.*)/resourceGroups/(?:.*)/providers/Microsoft.Compute/disks/(.+) I1001 18:05:32.971] • I1001 18:05:32.971] ------------------------------ I1001 18:05:32.971] Controller Service ControllerPublishVolume I1001 18:05:32.971] should fail when the node does not exist I1001 18:05:32.972] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:886 I1001 18:05:32.972] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:32.972] STEP: creating mount and staging directories I1001 18:05:32.972] I1001 18:05:32.963446 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:32.973] I1001 18:05:32.963478 8886 utils.go:113] GRPC request: I1001 18:05:32.973] I1001 18:05:32.963485 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:32.973] I1001 18:05:32.963491 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:32.973] STEP: creating a single node writer volume I1001 18:05:32.974] I1001 18:05:32.964005 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:32.974] I1001 18:05:32.964045 8886 utils.go:113] GRPC request: name:"sanity-controller-wrong-node-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:05:33.045] I1001 18:05:33.045053 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-wrong-node-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) I1001 18:05:33.045] I1001 18:05:33.045099 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-wrong-node-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:33.670] I1001 18:05:33.670068 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-wrong-node-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:33.671] I1001 18:05:33.670117 8886 controllerserver.go:222] create azure disk(sanity-controller-wrong-node-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) successfully I1001 18:05:33.671] I1001 18:05:33.670130 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:33.671] STEP: calling controllerpublish on that volume I1001 18:05:33.672] I1001 18:05:33.670939 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:33.672] I1001 18:05:33.670983 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA" node_id:"some-fake-node-id" volume_capability: access_mode: > I1001 18:05:33.672] I1001 18:05:33.670999 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId:/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA NodeId:some-fake-node-id VolumeCapability:mount:<> access_mode: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:33.771] I1001 18:05:33.771528 8886 controllerserver.go:326] GetDiskLun returned: . Initiating attaching volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA" to node "some-fake-node-id". I1001 18:05:33.881] I1001 18:05:33.881143 8886 azure_wrap.go:222] Virtual machine "some-fake-node-id" not found with message: "compute.VirtualMachinesClient#Get: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code=\"ResourceNotFound\" Message=\"The Resource 'Microsoft.Compute/virtualMachines/some-fake-node-id' under resource group 'azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc' was not found.\"" I1001 18:05:33.881] E1001 18:05:33.881192 8886 azure_controller_common.go:193] error of getting data disks for node "some-fake-node-id": instance not found I1001 18:05:33.882] E1001 18:05:33.881217 8886 utils.go:117] GRPC error: rpc error: code = NotFound desc = failed to get azure instance id for node "some-fake-node-id" (instance not found) I1001 18:05:33.882] STEP: cleaning up deleting the volume I1001 18:05:33.882] I1001 18:05:33.881747 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:33.883] I1001 18:05:33.881774 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA" I1001 18:05:33.883] I1001 18:05:33.881788 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA) I1001 18:05:34.270] I1001 18:05:34.270079 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA I1001 18:05:34.271] I1001 18:05:34.270131 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-wrong-node-7632817E-817F5FAA) successfully I1001 18:05:34.271] I1001 18:05:34.270140 8886 utils.go:119] GRPC response: I1001 18:05:34.271] • I1001 18:05:34.271] ------------------------------ I1001 18:05:34.272] Controller Service ControllerPublishVolume I1001 18:05:34.272] should fail when the volume is already published but is incompatible I1001 18:05:34.272] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:956 I1001 18:05:34.272] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:34.272] STEP: creating mount and staging directories I1001 18:05:34.273] I1001 18:05:34.270729 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:34.273] I1001 18:05:34.270765 8886 utils.go:113] GRPC request: I1001 18:05:34.273] I1001 18:05:34.270775 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:34.274] I1001 18:05:34.270782 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:34.274] I1001 18:05:34.271318 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:34.274] I1001 18:05:34.271346 8886 utils.go:113] GRPC request: I1001 18:05:34.275] I1001 18:05:34.271354 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:34.275] I1001 18:05:34.271361 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:34.275] I1001 18:05:34.275] S [SKIPPING] [0.002 seconds] I1001 18:05:34.275] Controller Service I1001 18:05:34.276] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:34.276] ControllerPublishVolume I1001 18:05:34.276] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:713 I1001 18:05:34.276] should fail when the volume is already published but is incompatible [It] I1001 18:05:34.277] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:956 I1001 18:05:34.277] I1001 18:05:34.277] ControllerPublishVolume.readonly field not supported I1001 18:05:34.277] I1001 18:05:34.278] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:958 I1001 18:05:34.278] ------------------------------ I1001 18:05:34.278] Controller Service ControllerUnpublishVolume I1001 18:05:34.278] should fail when no volume id is provided I1001 18:05:34.278] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1066 I1001 18:05:34.279] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:34.279] STEP: creating mount and staging directories I1001 18:05:34.279] I1001 18:05:34.272745 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:34.279] I1001 18:05:34.272770 8886 utils.go:113] GRPC request: I1001 18:05:34.280] I1001 18:05:34.272775 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:34.280] I1001 18:05:34.272780 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:34.280] I1001 18:05:34.273554 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerUnpublishVolume I1001 18:05:34.280] I1001 18:05:34.273596 8886 utils.go:113] GRPC request: I1001 18:05:34.281] I1001 18:05:34.273608 8886 controllerserver.go:360] ControllerUnpublishVolume: called with args {VolumeId: NodeId: Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:34.281] E1001 18:05:34.273652 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID not provided I1001 18:05:34.281] • I1001 18:05:34.281] ------------------------------ I1001 18:05:34.282] Controller Service ControllerUnpublishVolume I1001 18:05:34.282] should return appropriate values (no optional values added) I1001 18:05:34.282] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1081 I1001 18:05:34.282] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:34.282] STEP: creating mount and staging directories I1001 18:05:34.283] I1001 18:05:34.274185 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:34.283] I1001 18:05:34.274211 8886 utils.go:113] GRPC request: I1001 18:05:34.283] I1001 18:05:34.274219 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:34.283] I1001 18:05:34.274225 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:34.284] STEP: creating a single node writer volume I1001 18:05:34.284] I1001 18:05:34.274976 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:34.284] I1001 18:05:34.275044 8886 utils.go:113] GRPC request: name:"sanity-controller-unpublish-7632817E-817F5FAA" volume_capabilities: access_mode: > I1001 18:05:34.367] I1001 18:05:34.367140 8886 controllerserver.go:175] begin to create azure disk(sanity-controller-unpublish-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) I1001 18:05:34.367] I1001 18:05:34.367168 8886 azuredisk.go:244] azureDisk - creating new managed Name:sanity-controller-unpublish-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:34.956] I1001 18:05:34.956590 8886 azuredisk.go:348] azureDisk - created new MD Name:sanity-controller-unpublish-7632817E-817F5FAA StorageAccountType:Standard_LRS Size:1 I1001 18:05:34.957] I1001 18:05:34.956646 8886 controllerserver.go:222] create azure disk(sanity-controller-unpublish-7632817E-817F5FAA) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(1) successfully I1001 18:05:34.957] I1001 18:05:34.956658 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:34.958] STEP: getting a node id I1001 18:05:34.958] I1001 18:05:34.957428 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetInfo I1001 18:05:34.958] I1001 18:05:34.957464 8886 utils.go:113] GRPC request: I1001 18:05:34.958] I1001 18:05:34.957473 8886 nodeserver.go:281] Using default NodeGetInfo I1001 18:05:35.039] I1001 18:05:35.038820 8886 azure_wrap.go:222] Virtual machine "CSINode" not found with message: "compute.VirtualMachinesClient#Get: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code=\"ResourceNotFound\" Message=\"The Resource 'Microsoft.Compute/virtualMachines/CSINode' under resource group 'azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc' was not found.\"" I1001 18:05:35.039] E1001 18:05:35.038873 8886 azure_standard.go:392] as.GetInstanceTypeByNodeName(CSINode) failed: as.getVirtualMachine(CSINode) err=instance not found I1001 18:05:35.039] W1001 18:05:35.038884 8886 nodeserver.go:290] Failed to get instance type from Azure cloud provider, nodeName: CSINode, error: instance not found I1001 18:05:35.040] I1001 18:05:35.038890 8886 utils.go:119] GRPC response: node_id:"CSINode" max_volumes_per_node:16 I1001 18:05:35.040] STEP: calling controllerpublish on that volume I1001 18:05:35.040] I1001 18:05:35.039531 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerPublishVolume I1001 18:05:35.040] I1001 18:05:35.039559 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA" node_id:"CSINode" volume_capability: access_mode: > I1001 18:05:35.041] I1001 18:05:35.039578 8886 controllerserver.go:294] ControllerPublishVolume: called with args {VolumeId:/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA NodeId:CSINode VolumeCapability:mount:<> access_mode: Readonly:false Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:05:35.138] I1001 18:05:35.138629 8886 controllerserver.go:326] GetDiskLun returned: . Initiating attaching volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA" to node "CSINode". I1001 18:05:35.230] I1001 18:05:35.230103 8886 azure_wrap.go:222] Virtual machine "CSINode" not found with message: "compute.VirtualMachinesClient#Get: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code=\"ResourceNotFound\" Message=\"The Resource 'Microsoft.Compute/virtualMachines/CSINode' under resource group 'azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc' was not found.\"" I1001 18:05:35.230] E1001 18:05:35.230150 8886 azure_controller_common.go:193] error of getting data disks for node "CSINode": instance not found I1001 18:05:35.231] E1001 18:05:35.230162 8886 utils.go:117] GRPC error: rpc error: code = NotFound desc = failed to get azure instance id for node "CSINode" (instance not found) I1001 18:05:35.231] cleanup: deleting sanity-controller-unpublish-7632817E-817F5FAA = /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA I1001 18:05:35.231] I1001 18:05:35.231251 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeUnpublishVolume I1001 18:05:35.232] I1001 18:05:35.231287 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA" target_path:"/tmp/csi" I1001 18:05:35.232] I1001 18:05:35.231310 8886 nodeserver.go:260] NodeUnpublishVolume: unmounting volume /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA on /tmp/csi I1001 18:05:35.232] I1001 18:05:35.231342 8886 mount_linux.go:209] Unmounting /tmp/csi I1001 18:05:35.234] E1001 18:05:35.233919 8886 utils.go:117] GRPC error: rpc error: code = Internal desc = Unmount failed: exit status 32 I1001 18:05:35.234] Unmounting arguments: /tmp/csi I1001 18:05:35.234] Output: umount: /tmp/csi: not mounted I1001 18:05:35.234] I1001 18:05:35.235] cleanup: warning: NodeUnpublishVolume: rpc error: code = Internal desc = Unmount failed: exit status 32 I1001 18:05:35.235] Unmounting arguments: /tmp/csi I1001 18:05:35.235] Output: umount: /tmp/csi: not mounted I1001 18:05:35.235] I1001 18:05:35.235] I1001 18:05:35.234473 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:35.236] I1001 18:05:35.234503 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA" I1001 18:05:35.236] I1001 18:05:35.234518 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA) I1001 18:05:35.595] I1001 18:05:35.594934 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA I1001 18:05:35.595] I1001 18:05:35.594966 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/sanity-controller-unpublish-7632817E-817F5FAA) successfully I1001 18:05:35.596] I1001 18:05:35.594975 8886 utils.go:119] GRPC response: I1001 18:05:35.596] I1001 18:05:35.596] • Failure [1.321 seconds] I1001 18:05:35.597] Controller Service I1001 18:05:35.597] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:35.597] ControllerUnpublishVolume I1001 18:05:35.597] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1059 I1001 18:05:35.598] should return appropriate values (no optional values added) [It] I1001 18:05:35.598] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1081 I1001 18:05:35.598] I1001 18:05:35.598] Unexpected error: I1001 18:05:35.599] <*status.statusError | 0xc0004e1bd0>: { I1001 18:05:35.599] Code: 5, I1001 18:05:35.599] Message: "failed to get azure instance id for node \"CSINode\" (instance not found)", I1001 18:05:35.599] Details: nil, I1001 18:05:35.600] XXX_NoUnkeyedLiteral: {}, I1001 18:05:35.600] XXX_unrecognized: nil, I1001 18:05:35.600] XXX_sizecache: 0, I1001 18:05:35.600] } I1001 18:05:35.601] rpc error: code = NotFound desc = failed to get azure instance id for node "CSINode" (instance not found) I1001 18:05:35.601] occurred I1001 18:05:35.601] I1001 18:05:35.602] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1139 I1001 18:05:35.602] ------------------------------ I1001 18:05:35.602] CreateSnapshot [Controller Server] I1001 18:05:35.602] should fail when no name is provided I1001 18:05:35.603] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1502 I1001 18:05:35.603] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:35.603] STEP: creating mount and staging directories I1001 18:05:35.604] I1001 18:05:35.595778 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:35.604] I1001 18:05:35.595825 8886 utils.go:113] GRPC request: I1001 18:05:35.604] I1001 18:05:35.595835 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:35.604] I1001 18:05:35.595842 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:35.605] I1001 18:05:35.596454 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:05:35.605] I1001 18:05:35.596489 8886 utils.go:113] GRPC request: source_volume_id:"testId" I1001 18:05:35.605] I1001 18:05:35.596501 8886 controllerserver.go:439] CreateSnapshot called with request {testId map[] map[] {} [] 0} I1001 18:05:35.606] E1001 18:05:35.596515 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Snapshot name must be provided I1001 18:05:35.606] • I1001 18:05:35.606] ------------------------------ I1001 18:05:35.606] CreateSnapshot [Controller Server] I1001 18:05:35.607] should fail when no source volume id is provided I1001 18:05:35.607] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1519 I1001 18:05:35.607] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:35.607] STEP: creating mount and staging directories I1001 18:05:35.608] I1001 18:05:35.596957 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:35.608] I1001 18:05:35.596988 8886 utils.go:113] GRPC request: I1001 18:05:35.608] I1001 18:05:35.596995 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:35.609] I1001 18:05:35.597001 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:35.609] I1001 18:05:35.598327 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:05:35.609] I1001 18:05:35.598358 8886 utils.go:113] GRPC request: name:"name" I1001 18:05:35.609] I1001 18:05:35.598365 8886 controllerserver.go:439] CreateSnapshot called with request { name map[] map[] {} [] 0} I1001 18:05:35.610] E1001 18:05:35.598382 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = CreateSnapshot Source Volume ID must be provided I1001 18:05:35.610] • I1001 18:05:35.610] ------------------------------ I1001 18:05:35.610] CreateSnapshot [Controller Server] I1001 18:05:35.611] should not fail when requesting to create a snapshot with already existing name and same SourceVolumeId. I1001 18:05:35.611] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1536 I1001 18:05:35.611] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:35.611] STEP: creating mount and staging directories I1001 18:05:35.611] I1001 18:05:35.598892 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:35.612] I1001 18:05:35.598915 8886 utils.go:113] GRPC request: I1001 18:05:35.612] I1001 18:05:35.598922 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:35.612] I1001 18:05:35.598932 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:35.612] STEP: creating a volume I1001 18:05:35.613] I1001 18:05:35.599503 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:35.613] I1001 18:05:35.599534 8886 utils.go:113] GRPC request: name:"CreateSnapshot-volume-1" capacity_range: volume_capabilities: access_mode: > I1001 18:05:35.689] I1001 18:05:35.688987 8886 controllerserver.go:175] begin to create azure disk(CreateSnapshot-volume-1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:05:35.689] I1001 18:05:35.689019 8886 azuredisk.go:244] azureDisk - creating new managed Name:CreateSnapshot-volume-1 StorageAccountType:Standard_LRS Size:10 I1001 18:05:36.276] I1001 18:05:36.275867 8886 azuredisk.go:348] azureDisk - created new MD Name:CreateSnapshot-volume-1 StorageAccountType:Standard_LRS Size:10 I1001 18:05:36.276] I1001 18:05:36.275915 8886 controllerserver.go:222] create azure disk(CreateSnapshot-volume-1) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:05:36.277] I1001 18:05:36.275925 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:36.277] STEP: creating a snapshot I1001 18:05:36.277] I1001 18:05:36.276717 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:05:36.277] I1001 18:05:36.276750 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1" name:"CreateSnapshot-snapshot-1" I1001 18:05:36.278] I1001 18:05:36.276768 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1 CreateSnapshot-snapshot-1 map[] map[] {} [] 0} I1001 18:05:36.278] I1001 18:05:36.276810 8886 controllerserver.go:463] begin to create snapshot(CreateSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:05:46.934] I1001 18:05:46.933725 8886 controllerserver.go:476] create snapshot(CreateSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:05:47.033] I1001 18:05:47.032845 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:05:47.033] I1001 18:05:47.033564 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:05:47.034] I1001 18:05:47.033608 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1" name:"CreateSnapshot-snapshot-1" I1001 18:05:47.034] I1001 18:05:47.033622 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1 CreateSnapshot-snapshot-1 map[] map[] {} [] 0} I1001 18:05:47.034] I1001 18:05:47.033653 8886 controllerserver.go:463] begin to create snapshot(CreateSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:05:47.432] I1001 18:05:47.432511 8886 controllerserver.go:476] create snapshot(CreateSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:05:47.530] I1001 18:05:47.530181 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:05:47.530] STEP: cleaning up deleting the snapshot I1001 18:05:47.531] I1001 18:05:47.530842 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:05:47.531] I1001 18:05:47.530870 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/CreateSnapshot-snapshot-1" I1001 18:05:47.531] I1001 18:05:47.530880 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/CreateSnapshot-snapshot-1 map[] {} [] 0} I1001 18:05:47.531] I1001 18:05:47.530938 8886 controllerserver.go:503] begin to delete snapshot(CreateSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:05:52.981] I1001 18:05:52.981386 8886 controllerserver.go:512] delete snapshot(CreateSnapshot-snapshot-1) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:05:52.982] I1001 18:05:52.981420 8886 utils.go:119] GRPC response: I1001 18:05:52.982] STEP: cleaning up deleting the volume I1001 18:05:52.982] I1001 18:05:52.982228 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:05:52.982] I1001 18:05:52.982252 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1" I1001 18:05:52.983] I1001 18:05:52.982264 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1) I1001 18:05:58.420] I1001 18:05:58.420641 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1 I1001 18:05:58.421] I1001 18:05:58.420670 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-1) successfully I1001 18:05:58.421] I1001 18:05:58.420677 8886 utils.go:119] GRPC response: I1001 18:05:58.421] I1001 18:05:58.422] • [SLOW TEST:22.822 seconds] I1001 18:05:58.422] CreateSnapshot [Controller Server] I1001 18:05:58.422] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:05:58.422] should not fail when requesting to create a snapshot with already existing name and same SourceVolumeId. I1001 18:05:58.422] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1536 I1001 18:05:58.422] ------------------------------ I1001 18:05:58.423] CreateSnapshot [Controller Server] I1001 18:05:58.423] should fail when requesting to create a snapshot with already existing name and different SourceVolumeId. I1001 18:05:58.423] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1566 I1001 18:05:58.423] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:05:58.423] STEP: creating mount and staging directories I1001 18:05:58.424] I1001 18:05:58.421320 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:05:58.424] I1001 18:05:58.421346 8886 utils.go:113] GRPC request: I1001 18:05:58.424] I1001 18:05:58.421353 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:05:58.424] I1001 18:05:58.421358 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:05:58.424] STEP: creating a volume I1001 18:05:58.424] I1001 18:05:58.421837 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:05:58.425] I1001 18:05:58.421862 8886 utils.go:113] GRPC request: name:"CreateSnapshot-volume-2" capacity_range: volume_capabilities: access_mode: > I1001 18:05:58.506] I1001 18:05:58.506631 8886 controllerserver.go:175] begin to create azure disk(CreateSnapshot-volume-2) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:05:58.507] I1001 18:05:58.506653 8886 azuredisk.go:244] azureDisk - creating new managed Name:CreateSnapshot-volume-2 StorageAccountType:Standard_LRS Size:10 I1001 18:05:59.165] I1001 18:05:59.165589 8886 azuredisk.go:348] azureDisk - created new MD Name:CreateSnapshot-volume-2 StorageAccountType:Standard_LRS Size:10 I1001 18:05:59.166] I1001 18:05:59.165630 8886 controllerserver.go:222] create azure disk(CreateSnapshot-volume-2) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:05:59.166] I1001 18:05:59.165641 8886 utils.go:119] GRPC response: volume: > > I1001 18:05:59.167] STEP: creating a snapshot with the created volume source id I1001 18:05:59.167] I1001 18:05:59.166379 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:05:59.167] I1001 18:05:59.166414 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-2" name:"CreateSnapshot-snapshot-2" I1001 18:05:59.167] I1001 18:05:59.166429 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-2 CreateSnapshot-snapshot-2 map[] map[] {} [] 0} I1001 18:05:59.168] I1001 18:05:59.166447 8886 controllerserver.go:463] begin to create snapshot(CreateSnapshot-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:06:09.841] I1001 18:06:09.841566 8886 controllerserver.go:476] create snapshot(CreateSnapshot-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:06:09.938] I1001 18:06:09.937895 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:06:09.938] I1001 18:06:09.938625 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:06:09.939] I1001 18:06:09.938661 8886 utils.go:113] GRPC request: name:"CreateSnapshot-volume-3" capacity_range: volume_capabilities: access_mode: > I1001 18:06:10.021] I1001 18:06:10.021311 8886 controllerserver.go:175] begin to create azure disk(CreateSnapshot-volume-3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:06:10.021] I1001 18:06:10.021342 8886 azuredisk.go:244] azureDisk - creating new managed Name:CreateSnapshot-volume-3 StorageAccountType:Standard_LRS Size:10 I1001 18:06:10.696] I1001 18:06:10.696022 8886 azuredisk.go:348] azureDisk - created new MD Name:CreateSnapshot-volume-3 StorageAccountType:Standard_LRS Size:10 I1001 18:06:10.696] I1001 18:06:10.696069 8886 controllerserver.go:222] create azure disk(CreateSnapshot-volume-3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:06:10.697] I1001 18:06:10.696083 8886 utils.go:119] GRPC response: volume: > > I1001 18:06:10.697] STEP: creating a snapshot with the same name but different volume source id I1001 18:06:10.697] I1001 18:06:10.696878 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:06:10.698] I1001 18:06:10.696908 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3" name:"CreateSnapshot-snapshot-2" I1001 18:06:10.698] I1001 18:06:10.696923 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3 CreateSnapshot-snapshot-2 map[] map[] {} [] 0} I1001 18:06:10.698] I1001 18:06:10.696950 8886 controllerserver.go:463] begin to create snapshot(CreateSnapshot-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:06:10.952] E1001 18:06:10.952354 8886 utils.go:117] GRPC error: rpc error: code = AlreadyExists desc = request snapshot(CreateSnapshot-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) already exists, but the SourceVolumeId is different, error details: compute.SnapshotsClient#CreateOrUpdate: Failure sending request: StatusCode=400 -- Original Error: Code="BadRequest" Message="Changing property 'sourceResourceId' is not allowed for existing disk 'CreateSnapshot-snapshot-2'." I1001 18:06:10.953] STEP: cleaning up deleting the snapshot I1001 18:06:10.953] I1001 18:06:10.952980 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:06:10.953] I1001 18:06:10.953041 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/CreateSnapshot-snapshot-2" I1001 18:06:10.954] I1001 18:06:10.953088 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/CreateSnapshot-snapshot-2 map[] {} [] 0} I1001 18:06:10.954] I1001 18:06:10.953160 8886 controllerserver.go:503] begin to delete snapshot(CreateSnapshot-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:06:16.393] I1001 18:06:16.393454 8886 controllerserver.go:512] delete snapshot(CreateSnapshot-snapshot-2) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:06:16.394] I1001 18:06:16.393486 8886 utils.go:119] GRPC response: I1001 18:06:16.394] STEP: cleaning up deleting the volume I1001 18:06:16.394] I1001 18:06:16.394199 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:06:16.395] I1001 18:06:16.394234 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-2" I1001 18:06:16.395] I1001 18:06:16.394259 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-2) I1001 18:06:21.868] I1001 18:06:21.867880 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-2 I1001 18:06:21.868] I1001 18:06:21.867921 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-2) successfully I1001 18:06:21.869] I1001 18:06:21.867936 8886 utils.go:119] GRPC response: I1001 18:06:21.869] I1001 18:06:21.869] • [SLOW TEST:23.447 seconds] I1001 18:06:21.869] CreateSnapshot [Controller Server] I1001 18:06:21.870] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:06:21.870] should fail when requesting to create a snapshot with already existing name and different SourceVolumeId. I1001 18:06:21.870] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1566 I1001 18:06:21.871] ------------------------------ I1001 18:06:21.871] CreateSnapshot [Controller Server] I1001 18:06:21.871] should not fail when creating snapshot with maximum-length name I1001 18:06:21.871] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1601 I1001 18:06:21.872] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:21.872] STEP: creating mount and staging directories I1001 18:06:21.872] I1001 18:06:21.868751 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:21.872] I1001 18:06:21.868802 8886 utils.go:113] GRPC request: I1001 18:06:21.873] I1001 18:06:21.868814 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:21.873] I1001 18:06:21.868820 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:21.873] STEP: creating a volume I1001 18:06:21.873] I1001 18:06:21.869602 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateVolume I1001 18:06:21.874] I1001 18:06:21.869638 8886 utils.go:113] GRPC request: name:"CreateSnapshot-volume-3" capacity_range: volume_capabilities: access_mode: > I1001 18:06:22.072] I1001 18:06:22.072421 8886 controllerserver.go:175] begin to create azure disk(CreateSnapshot-volume-3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) I1001 18:06:22.073] I1001 18:06:22.072452 8886 azuredisk.go:244] azureDisk - creating new managed Name:CreateSnapshot-volume-3 StorageAccountType:Standard_LRS Size:10 I1001 18:06:34.560] I1001 18:06:34.560317 8886 azuredisk.go:348] azureDisk - created new MD Name:CreateSnapshot-volume-3 StorageAccountType:Standard_LRS Size:10 I1001 18:06:34.561] I1001 18:06:34.560363 8886 controllerserver.go:222] create azure disk(CreateSnapshot-volume-3) account type(Standard_LRS) rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) location() size(10) successfully I1001 18:06:34.561] I1001 18:06:34.560377 8886 utils.go:119] GRPC response: volume: > > I1001 18:06:34.562] STEP: creating a snapshot I1001 18:06:34.562] I1001 18:06:34.561265 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:06:34.562] I1001 18:06:34.561305 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3" name:"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" I1001 18:06:34.563] I1001 18:06:34.561326 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa map[] map[] {} [] 0} I1001 18:06:34.563] W1001 18:06:34.561346 8886 azuredisk.go:368] since the maximum volume name length is 80, so it is truncated as ("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa") I1001 18:06:34.563] I1001 18:06:34.561360 8886 controllerserver.go:463] begin to create snapshot(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:06:45.348] I1001 18:06:45.347930 8886 controllerserver.go:476] create snapshot(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:06:45.437] I1001 18:06:45.436969 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:06:45.437] I1001 18:06:45.437590 8886 utils.go:112] GRPC call: /csi.v1.Controller/CreateSnapshot I1001 18:06:45.438] I1001 18:06:45.437623 8886 utils.go:113] GRPC request: source_volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3" name:"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" I1001 18:06:45.438] I1001 18:06:45.437636 8886 controllerserver.go:439] CreateSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa map[] map[] {} [] 0} I1001 18:06:45.438] W1001 18:06:45.437659 8886 azuredisk.go:368] since the maximum volume name length is 80, so it is truncated as ("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa") I1001 18:06:45.439] I1001 18:06:45.437677 8886 controllerserver.go:463] begin to create snapshot(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:06:45.822] I1001 18:06:45.822088 8886 controllerserver.go:476] create snapshot(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:06:45.959] I1001 18:06:45.958750 8886 utils.go:119] GRPC response: snapshot: ready_to_use:true > I1001 18:06:45.959] STEP: cleaning up deleting the snapshot I1001 18:06:45.959] I1001 18:06:45.959493 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteSnapshot I1001 18:06:45.960] I1001 18:06:45.959525 8886 utils.go:113] GRPC request: snapshot_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" I1001 18:06:45.960] I1001 18:06:45.959537 8886 controllerserver.go:491] DeleteSnapshot called with request {/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/snapshots/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa map[] {} [] 0} I1001 18:06:45.960] I1001 18:06:45.959609 8886 controllerserver.go:503] begin to delete snapshot(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) I1001 18:06:51.440] I1001 18:06:51.440171 8886 controllerserver.go:512] delete snapshot(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) under rg(azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc) successfully I1001 18:06:51.440] I1001 18:06:51.440208 8886 utils.go:119] GRPC response: I1001 18:06:51.441] STEP: cleaning up deleting the volume I1001 18:06:51.441] I1001 18:06:51.440920 8886 utils.go:112] GRPC call: /csi.v1.Controller/DeleteVolume I1001 18:06:51.441] I1001 18:06:51.440960 8886 utils.go:113] GRPC request: volume_id:"/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3" I1001 18:06:51.442] I1001 18:06:51.440977 8886 controllerserver.go:277] deleting azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3) I1001 18:06:56.881] I1001 18:06:56.881319 8886 azure_managedDiskController.go:195] azureDisk - deleted a managed disk: /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3 I1001 18:06:56.882] I1001 18:06:56.881356 8886 controllerserver.go:287] delete azure disk(/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc/providers/Microsoft.Compute/disks/CreateSnapshot-volume-3) successfully I1001 18:06:56.882] I1001 18:06:56.881370 8886 utils.go:119] GRPC response: I1001 18:06:56.882] I1001 18:06:56.883] • [SLOW TEST:35.013 seconds] I1001 18:06:56.883] CreateSnapshot [Controller Server] I1001 18:06:56.883] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 I1001 18:06:56.884] should not fail when creating snapshot with maximum-length name I1001 18:06:56.884] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1601 I1001 18:06:56.884] ------------------------------ I1001 18:06:56.885] Node Service NodeGetCapabilities I1001 18:06:56.885] should return appropriate capabilities I1001 18:06:56.885] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:107 I1001 18:06:56.885] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:56.886] STEP: creating mount and staging directories I1001 18:06:56.886] I1001 18:06:56.882302 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:56.886] I1001 18:06:56.882342 8886 utils.go:113] GRPC request: I1001 18:06:56.887] I1001 18:06:56.882352 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:56.887] I1001 18:06:56.882359 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:56.887] I1001 18:06:56.883121 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:56.887] I1001 18:06:56.883154 8886 utils.go:113] GRPC request: I1001 18:06:56.887] I1001 18:06:56.883164 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:56.888] I1001 18:06:56.883171 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:56.888] I1001 18:06:56.883842 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:56.888] I1001 18:06:56.883873 8886 utils.go:113] GRPC request: I1001 18:06:56.888] I1001 18:06:56.883883 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:56.888] I1001 18:06:56.883890 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:56.889] STEP: checking successful response I1001 18:06:56.889] • I1001 18:06:56.889] ------------------------------ I1001 18:06:56.889] Node Service NodeGetInfo I1001 18:06:56.889] should return approproate values I1001 18:06:56.889] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:141 I1001 18:06:56.890] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:56.890] STEP: creating mount and staging directories I1001 18:06:56.890] I1001 18:06:56.884486 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:56.890] I1001 18:06:56.884511 8886 utils.go:113] GRPC request: I1001 18:06:56.890] I1001 18:06:56.884519 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:56.891] I1001 18:06:56.884525 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:56.891] I1001 18:06:56.885134 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:56.891] I1001 18:06:56.885177 8886 utils.go:113] GRPC request: I1001 18:06:56.891] I1001 18:06:56.885188 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:56.891] I1001 18:06:56.885195 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:56.892] I1001 18:06:56.885662 8886 utils.go:112] GRPC call: /csi.v1.Identity/GetPluginCapabilities I1001 18:06:56.892] I1001 18:06:56.885702 8886 utils.go:113] GRPC request: I1001 18:06:56.892] I1001 18:06:56.885708 8886 identityserver.go:59] Using default capabilities I1001 18:06:56.892] I1001 18:06:56.885714 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:56.892] I1001 18:06:56.886219 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetInfo I1001 18:06:56.893] I1001 18:06:56.886250 8886 utils.go:113] GRPC request: I1001 18:06:56.893] I1001 18:06:56.886259 8886 nodeserver.go:281] Using default NodeGetInfo I1001 18:06:56.893] I1001 18:06:56.886301 8886 expiration_cache.go:101] Entry CSINode: &{key:CSINode data: lock:{state:0 sema:0}} has expired I1001 18:06:57.016] I1001 18:06:57.015996 8886 azure_wrap.go:222] Virtual machine "CSINode" not found with message: "compute.VirtualMachinesClient#Get: Failure responding to request: StatusCode=404 -- Original Error: autorest/azure: Service returned an error. Status=404 Code=\"ResourceNotFound\" Message=\"The Resource 'Microsoft.Compute/virtualMachines/CSINode' under resource group 'azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc' was not found.\"" I1001 18:06:57.016] E1001 18:06:57.016036 8886 azure_standard.go:392] as.GetInstanceTypeByNodeName(CSINode) failed: as.getVirtualMachine(CSINode) err=instance not found I1001 18:06:57.017] W1001 18:06:57.016047 8886 nodeserver.go:290] Failed to get instance type from Azure cloud provider, nodeName: CSINode, error: instance not found I1001 18:06:57.017] I1001 18:06:57.016053 8886 utils.go:119] GRPC response: node_id:"CSINode" max_volumes_per_node:16 I1001 18:06:57.017] • I1001 18:06:57.017] ------------------------------ I1001 18:06:57.018] Node Service NodePublishVolume I1001 18:06:57.018] should fail when no volume id is provided I1001 18:06:57.018] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:158 I1001 18:06:57.019] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.019] STEP: creating mount and staging directories I1001 18:06:57.019] I1001 18:06:57.016602 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.019] I1001 18:06:57.016619 8886 utils.go:113] GRPC request: I1001 18:06:57.020] I1001 18:06:57.016624 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.020] I1001 18:06:57.016630 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.020] I1001 18:06:57.017140 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.021] I1001 18:06:57.017168 8886 utils.go:113] GRPC request: I1001 18:06:57.021] I1001 18:06:57.017176 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.021] I1001 18:06:57.017182 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.021] I1001 18:06:57.017919 8886 utils.go:112] GRPC call: /csi.v1.Node/NodePublishVolume I1001 18:06:57.022] I1001 18:06:57.017986 8886 utils.go:113] GRPC request: I1001 18:06:57.022] E1001 18:06:57.017996 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capability missing in request I1001 18:06:57.022] • I1001 18:06:57.022] ------------------------------ I1001 18:06:57.023] Node Service NodePublishVolume I1001 18:06:57.023] should fail when no target path is provided I1001 18:06:57.023] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:172 I1001 18:06:57.023] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.024] STEP: creating mount and staging directories I1001 18:06:57.024] I1001 18:06:57.018545 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.024] I1001 18:06:57.018580 8886 utils.go:113] GRPC request: I1001 18:06:57.024] I1001 18:06:57.018590 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.025] I1001 18:06:57.018598 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.025] I1001 18:06:57.019111 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.025] I1001 18:06:57.019134 8886 utils.go:113] GRPC request: I1001 18:06:57.025] I1001 18:06:57.019141 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.026] I1001 18:06:57.019148 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.026] I1001 18:06:57.019606 8886 utils.go:112] GRPC call: /csi.v1.Node/NodePublishVolume I1001 18:06:57.026] I1001 18:06:57.019634 8886 utils.go:113] GRPC request: volume_id:"id" I1001 18:06:57.027] E1001 18:06:57.019640 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capability missing in request I1001 18:06:57.027] • I1001 18:06:57.027] ------------------------------ I1001 18:06:57.027] Node Service NodePublishVolume I1001 18:06:57.028] should fail when no volume capability is provided I1001 18:06:57.028] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:187 I1001 18:06:57.028] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.028] STEP: creating mount and staging directories I1001 18:06:57.029] I1001 18:06:57.020008 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.029] I1001 18:06:57.020030 8886 utils.go:113] GRPC request: I1001 18:06:57.029] I1001 18:06:57.020038 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.030] I1001 18:06:57.020045 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.030] I1001 18:06:57.020470 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.030] I1001 18:06:57.020492 8886 utils.go:113] GRPC request: I1001 18:06:57.031] I1001 18:06:57.020503 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.031] I1001 18:06:57.020510 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.031] I1001 18:06:57.021037 8886 utils.go:112] GRPC call: /csi.v1.Node/NodePublishVolume I1001 18:06:57.031] I1001 18:06:57.021072 8886 utils.go:113] GRPC request: volume_id:"id" target_path:"/tmp/csi" I1001 18:06:57.032] E1001 18:06:57.021094 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capability missing in request I1001 18:06:57.032] • I1001 18:06:57.032] ------------------------------ I1001 18:06:57.032] Node Service NodeUnpublishVolume I1001 18:06:57.032] should fail when no volume id is provided I1001 18:06:57.032] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:205 I1001 18:06:57.033] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.033] STEP: creating mount and staging directories I1001 18:06:57.033] I1001 18:06:57.021493 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.033] I1001 18:06:57.021520 8886 utils.go:113] GRPC request: I1001 18:06:57.034] I1001 18:06:57.021528 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.034] I1001 18:06:57.021535 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.034] I1001 18:06:57.021949 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.034] I1001 18:06:57.021983 8886 utils.go:113] GRPC request: I1001 18:06:57.035] I1001 18:06:57.021992 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.035] I1001 18:06:57.021998 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.035] I1001 18:06:57.022366 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeUnpublishVolume I1001 18:06:57.035] I1001 18:06:57.022390 8886 utils.go:113] GRPC request: I1001 18:06:57.035] E1001 18:06:57.022398 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID missing in request I1001 18:06:57.036] • I1001 18:06:57.036] ------------------------------ I1001 18:06:57.036] Node Service NodeUnpublishVolume I1001 18:06:57.036] should fail when no target path is provided I1001 18:06:57.036] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:217 I1001 18:06:57.037] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.037] STEP: creating mount and staging directories I1001 18:06:57.037] I1001 18:06:57.022796 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.037] I1001 18:06:57.022816 8886 utils.go:113] GRPC request: I1001 18:06:57.037] I1001 18:06:57.022821 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.038] I1001 18:06:57.022825 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.038] I1001 18:06:57.023281 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.038] I1001 18:06:57.023308 8886 utils.go:113] GRPC request: I1001 18:06:57.038] I1001 18:06:57.023316 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.038] I1001 18:06:57.023322 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.039] I1001 18:06:57.023751 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeUnpublishVolume I1001 18:06:57.039] I1001 18:06:57.023773 8886 utils.go:113] GRPC request: volume_id:"id" I1001 18:06:57.039] E1001 18:06:57.023786 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Target path missing in request I1001 18:06:57.039] • I1001 18:06:57.040] ------------------------------ I1001 18:06:57.040] Node Service NodeStageVolume I1001 18:06:57.040] should fail when no volume id is provided I1001 18:06:57.041] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:245 I1001 18:06:57.041] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.041] STEP: creating mount and staging directories I1001 18:06:57.042] I1001 18:06:57.024240 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.042] I1001 18:06:57.024269 8886 utils.go:113] GRPC request: I1001 18:06:57.042] I1001 18:06:57.024277 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.043] I1001 18:06:57.024284 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.043] I1001 18:06:57.024767 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.043] I1001 18:06:57.024803 8886 utils.go:113] GRPC request: I1001 18:06:57.043] I1001 18:06:57.024810 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.044] I1001 18:06:57.024815 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.044] I1001 18:06:57.025326 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeStageVolume I1001 18:06:57.045] I1001 18:06:57.025356 8886 utils.go:113] GRPC request: publish_context: staging_target_path:"/tmp/csi" volume_capability: access_mode: > I1001 18:06:57.045] I1001 18:06:57.025370 8886 nodeserver.go:50] NodeStageVolume: called with args {VolumeId: PublishContext:map[device:/dev/mock] StagingTargetPath:/tmp/csi VolumeCapability:mount:<> access_mode: Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:06:57.045] E1001 18:06:57.025423 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID not provided I1001 18:06:57.046] • I1001 18:06:57.046] ------------------------------ I1001 18:06:57.046] Node Service NodeStageVolume I1001 18:06:57.046] should fail when no staging target path is provided I1001 18:06:57.047] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:271 I1001 18:06:57.047] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.047] STEP: creating mount and staging directories I1001 18:06:57.048] I1001 18:06:57.025905 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.048] I1001 18:06:57.025951 8886 utils.go:113] GRPC request: I1001 18:06:57.048] I1001 18:06:57.025961 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.049] I1001 18:06:57.025967 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.049] I1001 18:06:57.026439 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.050] I1001 18:06:57.026491 8886 utils.go:113] GRPC request: I1001 18:06:57.050] I1001 18:06:57.026502 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.050] I1001 18:06:57.026509 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.051] I1001 18:06:57.027028 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeStageVolume I1001 18:06:57.051] I1001 18:06:57.027057 8886 utils.go:113] GRPC request: volume_id:"id" publish_context: volume_capability: access_mode: > I1001 18:06:57.052] I1001 18:06:57.027070 8886 nodeserver.go:50] NodeStageVolume: called with args {VolumeId:id PublishContext:map[device:/dev/mock] StagingTargetPath: VolumeCapability:mount:<> access_mode: Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:06:57.052] E1001 18:06:57.027134 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Staging target not provided I1001 18:06:57.053] • I1001 18:06:57.053] ------------------------------ I1001 18:06:57.053] Node Service NodeStageVolume I1001 18:06:57.054] should fail when no volume capability is provided I1001 18:06:57.054] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:297 I1001 18:06:57.054] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.055] STEP: creating mount and staging directories I1001 18:06:57.055] I1001 18:06:57.027606 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.055] I1001 18:06:57.027639 8886 utils.go:113] GRPC request: I1001 18:06:57.055] I1001 18:06:57.027648 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.056] I1001 18:06:57.027667 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.056] I1001 18:06:57.028121 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.056] I1001 18:06:57.028162 8886 utils.go:113] GRPC request: I1001 18:06:57.057] I1001 18:06:57.028169 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.057] I1001 18:06:57.028176 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.057] I1001 18:06:57.028687 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeStageVolume I1001 18:06:57.058] I1001 18:06:57.028752 8886 utils.go:113] GRPC request: volume_id:"id" publish_context: staging_target_path:"/tmp/csi" I1001 18:06:57.058] I1001 18:06:57.028765 8886 nodeserver.go:50] NodeStageVolume: called with args {VolumeId:id PublishContext:map[device:/dev/mock] StagingTargetPath:/tmp/csi VolumeCapability: Secrets:map[] VolumeContext:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:06:57.058] E1001 18:06:57.028806 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume capability not provided I1001 18:06:57.059] • I1001 18:06:57.059] ------------------------------ I1001 18:06:57.059] Node Service NodeUnstageVolume I1001 18:06:57.059] should fail when no volume id is provided I1001 18:06:57.060] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:324 I1001 18:06:57.060] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.060] STEP: creating mount and staging directories I1001 18:06:57.061] I1001 18:06:57.029314 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.061] I1001 18:06:57.029340 8886 utils.go:113] GRPC request: I1001 18:06:57.061] I1001 18:06:57.029348 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.062] I1001 18:06:57.029354 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.062] I1001 18:06:57.029813 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.062] I1001 18:06:57.029834 8886 utils.go:113] GRPC request: I1001 18:06:57.062] I1001 18:06:57.029841 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.063] I1001 18:06:57.029847 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.063] I1001 18:06:57.030303 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeUnstageVolume I1001 18:06:57.064] I1001 18:06:57.030334 8886 utils.go:113] GRPC request: staging_target_path:"/tmp/csi" I1001 18:06:57.064] I1001 18:06:57.030343 8886 nodeserver.go:146] NodeUnstageVolume: called with args {VolumeId: StagingTargetPath:/tmp/csi XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:06:57.064] E1001 18:06:57.030361 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Volume ID not provided I1001 18:06:57.064] • I1001 18:06:57.065] ------------------------------ I1001 18:06:57.065] Node Service NodeUnstageVolume I1001 18:06:57.065] should fail when no staging target path is provided I1001 18:06:57.065] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:338 I1001 18:06:57.066] STEP: reusing connection to CSI driver at unix:///tmp/csi.sock I1001 18:06:57.066] STEP: creating mount and staging directories I1001 18:06:57.066] I1001 18:06:57.030778 8886 utils.go:112] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I1001 18:06:57.066] I1001 18:06:57.030797 8886 utils.go:113] GRPC request: I1001 18:06:57.067] I1001 18:06:57.030802 8886 controllerserver.go:415] Using default ControllerGetCapabilities I1001 18:06:57.067] I1001 18:06:57.030806 8886 utils.go:119] GRPC response: capabilities: > capabilities: > capabilities: > capabilities: > I1001 18:06:57.068] I1001 18:06:57.031186 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeGetCapabilities I1001 18:06:57.068] I1001 18:06:57.031212 8886 utils.go:113] GRPC request: I1001 18:06:57.068] I1001 18:06:57.031220 8886 nodeserver.go:272] Using default NodeGetCapabilities I1001 18:06:57.068] I1001 18:06:57.031228 8886 utils.go:119] GRPC response: capabilities: > I1001 18:06:57.069] I1001 18:06:57.031725 8886 utils.go:112] GRPC call: /csi.v1.Node/NodeUnstageVolume I1001 18:06:57.069] I1001 18:06:57.031760 8886 utils.go:113] GRPC request: volume_id:"id" I1001 18:06:57.069] I1001 18:06:57.031778 8886 nodeserver.go:146] NodeUnstageVolume: called with args {VolumeId:id StagingTargetPath: XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} I1001 18:06:57.070] E1001 18:06:57.031816 8886 utils.go:117] GRPC error: rpc error: code = InvalidArgument desc = Staging target not provided I1001 18:06:57.070] •S I1001 18:06:57.070] I1001 18:06:57.070] Summarizing 2 Failures: I1001 18:06:57.070] I1001 18:06:57.071] [Fail] Controller Service ControllerPublishVolume [It] should return appropriate values (no optional values added) I1001 18:06:57.071] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:826 I1001 18:06:57.071] I1001 18:06:57.071] [Fail] Controller Service ControllerUnpublishVolume [It] should return appropriate values (no optional values added) I1001 18:06:57.072] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1139 I1001 18:06:57.072] I1001 18:06:57.072] Ran 53 of 57 Specs in 373.405 seconds I1001 18:06:57.072] FAIL! -- 51 Passed | 2 Failed | 0 Pending | 4 Skipped I1001 18:06:57.073] --- FAIL: TestSanity (373.41s) I1001 18:06:57.073] FAIL I1001 18:06:57.073] pkill -f azurediskplugin I1001 18:06:57.073] Deleting CSI sanity test binary I1001 18:06:57.082] test/sanity/run-test.sh: line 19: 8886 Terminated _output/azurediskplugin --endpoint "$endpoint" --nodeid "$nodeid" -v=5 I1001 18:06:57.083] 2019/10/01 18:06:57 Deleting resource group azuredisk-csi-driver-test-517a08e9-e475-11e9-9808-0a4a45922cfc I1001 18:08:59.820] --- FAIL: TestSanity (525.74s) I1001 18:08:59.821] sanity_test.go:78: Sanity test failed exit status 1 I1001 18:08:59.821] FAIL I1001 18:08:59.822] FAIL github.com/kubernetes-sigs/azuredisk-csi-driver/test/sanity 525.758s I1001 18:08:59.863] Makefile:51: recipe for target 'sanity-test' failed W1001 18:08:59.868] make: *** [sanity-test] Error 1 W1001 18:08:59.868] Traceback (most recent call last): W1001 18:08:59.868] File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 50, in W1001 18:08:59.868] main(ARGS.env, ARGS.cmd + ARGS.args) W1001 18:08:59.868] File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 41, in main W1001 18:08:59.869] check(*cmd) W1001 18:08:59.869] File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 30, in check W1001 18:08:59.869] subprocess.check_call(cmd) W1001 18:08:59.869] File "/usr/lib/python2.7/subprocess.py", line 186, in check_call W1001 18:08:59.869] raise CalledProcessError(retcode, cmd) W1001 18:08:59.870] subprocess.CalledProcessError: Command '('make', 'sanity-test')' returned non-zero exit status 2 E1001 18:08:59.870] Command failed I1001 18:08:59.870] process 456 exited with code 1 after 11.2m E1001 18:08:59.870] FAIL: pull-azuredisk-csi-driver-sanity I1001 18:08:59.870] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1001 18:09:01.449] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1001 18:09:01.487] process 8919 exited with code 0 after 0.0m I1001 18:09:01.487] Call: gcloud config get-value account I1001 18:09:01.736] process 8931 exited with code 0 after 0.0m I1001 18:09:01.737] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1001 18:09:01.737] Upload result and artifacts... I1001 18:09:01.737] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/1179092917625556994 W1001 18:09:01.737] Missing local artifacts : /workspace/_artifacts W1001 18:09:01.737] metadata path /workspace/_artifacts/metadata.json does not exist W1001 18:09:01.737] metadata not found or invalid, init with empty metadata I1001 18:09:01.737] Call: git rev-parse HEAD I1001 18:09:01.740] process 8943 exited with code 0 after 0.0m I1001 18:09:01.740] Call: git rev-parse HEAD I1001 18:09:01.742] process 8944 exited with code 0 after 0.0m I1001 18:09:01.743] Call: gsutil stat gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-sanity/jobResultsCache.json I1001 18:09:02.795] process 8945 exited with code 0 after 0.0m I1001 18:09:02.796] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-sanity/jobResultsCache.json#1569951961337143' I1001 18:09:04.016] process 9087 exited with code 0 after 0.0m I1001 18:09:04.017] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1569951961337143 cp /tmp/gsutil_nO5CCw gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-sanity/jobResultsCache.json I1001 18:09:05.284] process 9231 exited with code 0 after 0.0m I1001 18:09:05.284] Call: gsutil stat gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/jobResultsCache.json I1001 18:09:06.261] process 9409 exited with code 0 after 0.0m I1001 18:09:06.261] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/jobResultsCache.json#1569951963544285' I1001 18:09:07.540] process 9551 exited with code 0 after 0.0m I1001 18:09:07.541] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1569951963544285 cp /tmp/gsutil_H7w5wq gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/jobResultsCache.json I1001 18:09:09.000] process 9695 exited with code 0 after 0.0m I1001 18:09:09.001] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_B4292X gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/1179092917625556994/finished.json I1001 18:09:10.443] process 9873 exited with code 0 after 0.0m I1001 18:09:10.444] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_GyOn_4 gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-sanity/latest-build.txt I1001 18:09:11.850] process 10051 exited with code 0 after 0.0m I1001 18:09:11.851] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_j1kN4h gs://kubernetes-upstream/pr-logs/directory/pull-azuredisk-csi-driver-sanity/latest-build.txt I1001 18:09:13.290] process 10229 exited with code 0 after 0.0m