This job view page is being replaced by Spyglass soon. Check out the new job view.
PRandyzhangx: feat: add DiskEncryptionType in storage class
ResultFAILURE
Tests 1 failed / 18 succeeded
Started2022-05-05 07:39
Elapsed1h26m
Revision0bf5485b52f17925d688415963c37775f22f4f58
Refs 1315

Test Failures


AzureDisk CSI Driver End-to-End Tests Pre-Provisioned [single-az] should use a pre-provisioned volume and mount it as readOnly in a pod [disk.csi.azure.com][windows] 14m8s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=AzureDisk\sCSI\sDriver\sEnd\-to\-End\sTests\sPre\-Provisioned\s\[single\-az\]\sshould\suse\sa\spre\-provisioned\svolume\sand\smount\sit\sas\sreadOnly\sin\sa\spod\s\[disk\.csi\.azure\.com\]\[windows\]$'
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:70
Expected
    <string>: 
to contain substring
    <string>: FileOpenFailure
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/pre_provisioned_read_only_volume_tester.go:60
				
				Click to see stdout/stderrfrom junit_01.xml

Filter through log files | View test history on testgrid


Show 18 Passed Tests

Show 40 Skipped Tests

Error lines from build-log.txt

... skipping 672 lines ...
certificate.cert-manager.io "selfsigned-cert" deleted
# Create secret for AzureClusterIdentity
./hack/create-identity-secret.sh
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
make[2]: Nothing to be done for 'kubectl'.
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Error from server (NotFound): secrets "cluster-identity-secret" not found
secret/cluster-identity-secret created
secret/cluster-identity-secret labeled
# Deploy CAPI
curl --retry 3 -sSL https://github.com/kubernetes-sigs/cluster-api/releases/download/v1.1.2/cluster-api-components.yaml | /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/envsubst-v2.0.0-20210730161058-179042472c46 | kubectl apply -f -
namespace/capi-system created
customresourcedefinition.apiextensions.k8s.io/clusterclasses.cluster.x-k8s.io created
... skipping 180 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11156  100 11156    0     0   217k      0 --:--:-- --:--:-- --:--:--  217k
Downloading https://get.helm.sh/helm-v3.8.2-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull capzci.azurecr.io/azuredisk-csi:v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b || make container-all push-manifest
Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b not found: manifest unknown: manifest tagged by "v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b" is not found
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver'
CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.driverVersion=v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=4d0016a42e8322c34e24b5663e71e1e536f02c7b -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2022-05-05T07:59:07Z -extldflags "-static""  -mod vendor -o _output/amd64/azurediskplugin.exe ./pkg/azurediskplugin
docker buildx rm container-builder || true
error: no builder "container-builder" found
docker buildx create --use --name=container-builder
container-builder
# enable qemu for arm64 build
# https://github.com/docker/buildx/issues/464#issuecomment-741507760
docker run --privileged --rm tonistiigi/binfmt --uninstall qemu-aarch64
Unable to find image 'tonistiigi/binfmt:latest' locally
... skipping 2063 lines ...
          image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.4.0"
          args:
            - "-csi-address=$(ADDRESS)"
            - "-v=2"
            - "-leader-election"
            - "--leader-election-namespace=kube-system"
            - '-handle-volume-inuse-error=false'
            - '-feature-gates=RecoverVolumeExpansionFailure=true'
            - "-timeout=240s"
          env:
            - name: ADDRESS
              value: /csi/csi.sock
          volumeMounts:
... skipping 124 lines ...
Go Version: go1.18.1
Platform: linux/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
STEP: Building a namespace api object, basename azuredisk
W0505 08:10:42.045870   36735 azure_disk_utils.go:166] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
W0505 08:10:42.054049   36735 azuredisk.go:188] DisableAvailabilitySetNodes for controller is set as false while current VMType is vmss
I0505 08:10:42.057449   36735 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME
I0505 08:10:42.057477   36735 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0505 08:10:42.057481   36735 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0505 08:10:42.057486   36735 driver.go:81] Enabling controller service capability: CLONE_VOLUME
I0505 08:10:42.057489   36735 driver.go:81] Enabling controller service capability: EXPAND_VOLUME
... skipping 18 lines ...
May  5 08:10:46.610: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-hmh9z] to have phase Bound
May  5 08:10:46.647: INFO: PersistentVolumeClaim pvc-hmh9z found and phase=Bound (36.843829ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod's command exits with an error
May  5 08:10:46.767: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-dwm8z" in namespace "azuredisk-8081" to be "Error status code"
May  5 08:10:46.810: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 43.178086ms
May  5 08:10:48.848: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 2.081447655s
May  5 08:10:50.886: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 4.119447113s
May  5 08:10:52.925: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 6.158029396s
May  5 08:10:54.964: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 8.196965333s
May  5 08:10:57.003: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 10.236097845s
... skipping 215 lines ...
May  5 08:18:17.985: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 7m31.218519471s
May  5 08:18:20.027: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 7m33.259630835s
May  5 08:18:22.068: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 7m35.30067944s
May  5 08:18:24.109: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 7m37.341928973s
May  5 08:18:26.152: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 7m39.384624515s
May  5 08:18:28.193: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Pending", Reason="", readiness=false. Elapsed: 7m41.425840689s
May  5 08:18:30.233: INFO: Pod "azuredisk-volume-tester-dwm8z": Phase="Failed", Reason="", readiness=false. Elapsed: 7m43.466201028s
STEP: Saw pod failure
May  5 08:18:30.233: INFO: Pod "azuredisk-volume-tester-dwm8z" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
May  5 08:18:30.289: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-dwm8z"
May  5 08:18:30.330: INFO: Pod azuredisk-volume-tester-dwm8z has the following logs: 
STEP: Deleting pod azuredisk-volume-tester-dwm8z in namespace azuredisk-8081
May  5 08:18:30.409: INFO: deleting PVC "azuredisk-8081"/"pvc-hmh9z"
May  5 08:18:30.409: INFO: Deleting PersistentVolumeClaim "pvc-hmh9z"
... skipping 83 lines ...
STEP: Found 10 events.
May  5 08:24:48.636: INFO: At 2022-05-05 08:10:46 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {default-scheduler } Scheduled: Successfully assigned azuredisk-8081/azuredisk-volume-tester-dwm8z to capz-nqwf-qb4nr
May  5 08:24:48.636: INFO: At 2022-05-05 08:10:58 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "azuredisk-8081-disk.csi.azure.com-preprovisioned-pv-9rn9m" 
May  5 08:24:48.636: INFO: At 2022-05-05 08:11:35 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
May  5 08:24:48.636: INFO: At 2022-05-05 08:16:29 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m53.5350816s
May  5 08:24:48.636: INFO: At 2022-05-05 08:16:29 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Created: Created container volume-tester
May  5 08:24:48.636: INFO: At 2022-05-05 08:18:29 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Failed: Error: context deadline exceeded
May  5 08:24:48.636: INFO: At 2022-05-05 08:18:30 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
May  5 08:24:48.636: INFO: At 2022-05-05 08:18:34 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Started: Started container volume-tester
May  5 08:24:48.636: INFO: At 2022-05-05 08:18:35 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} Killing: Stopping container volume-tester
May  5 08:24:48.636: INFO: At 2022-05-05 08:20:36 +0000 UTC - event for azuredisk-volume-tester-dwm8z: {kubelet capz-nqwf-qb4nr} FailedKillPod: error killing pod: failed to "KillPodSandbox" for "6f2313c4-b433-4040-8683-9d4a5d16c53e" with KillPodSandboxError: "rpc error: code = DeadlineExceeded desc = context deadline exceeded"
May  5 08:24:48.673: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
May  5 08:24:48.673: INFO: 
May  5 08:24:48.726: INFO: 
Logging node info for node capz-nqwf-mbpbk
May  5 08:24:48.768: INFO: Node Info: &Node{ObjectMeta:{capz-nqwf-mbpbk    b791c43f-2f08-402c-a9d3-7053ab71a1a5 3845 0 2022-05-05 07:55:42 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:Standard_D4s_v3 beta.kubernetes.io/os:windows failure-domain.beta.kubernetes.io/region:eastus failure-domain.beta.kubernetes.io/zone:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-nqwf-mbpbk kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.disk.csi.azure.com/zone: topology.kubernetes.io/region:eastus topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-nqwflh cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-nqwflh-md-win-7f57f4569b-tt9v4 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-nqwflh-md-win-7f57f4569b csi.volume.kubernetes.io/nodeid:{"disk.csi.azure.com":"capz-nqwf-mbpbk"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.5/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.165.65 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:75:94:a6 volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-05-05 07:55:42 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-05-05 07:55:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-05-05 07:57:01 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-05-05 07:57:49 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-05-05 08:10:41 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}},"f:labels":{"f:topology.disk.csi.azure.com/zone":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/virtualMachines/capz-nqwf-mbpbk,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{17179398144 0} {<nil>} 16776756Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-05 08:21:01 +0000 UTC,LastTransitionTime:2022-05-05 07:55:42 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-05 08:21:01 +0000 UTC,LastTransitionTime:2022-05-05 07:55:42 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-05 08:21:01 +0000 UTC,LastTransitionTime:2022-05-05 07:55:42 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-05 08:21:01 +0000 UTC,LastTransitionTime:2022-05-05 07:57:03 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-nqwf-mbpbk,},NodeAddress{Type:InternalIP,Address:10.1.0.5,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-nqwf-mbpbk,SystemUUID:C59396A1-5A4F-4C72-B404-CC4476636613,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/eventflow-logger@sha256:63bf2aa9db909d0d90fb5205abf7fb2a6d9a494b89cbd2508a42457dfc875505 ghcr.io/kubernetes-sigs/sig-windows/eventflow-logger:v0.1.0],SizeBytes:148054279,},ContainerImage{Names:[capzci.azurecr.io/azuredisk-csi@sha256:4e894cde672183a79e0509db1fa8af0efa5ea0d4702862f2065a9d31e5f36700 capzci.azurecr.io/azuredisk-csi:v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b],SizeBytes:141911467,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:348b2d4eebc8da38687755a69b6c21035be232325a6bcde54e5ec4e04689fd93 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.5.0],SizeBytes:125796204,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:e01f5dae19d7e1be536606fe5deb893417429486b628b816d80ffa0e441eeae8 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.6.0],SizeBytes:124893309,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
May  5 08:24:48.770: INFO: 
... skipping 145 lines ...

May  5 08:24:58.815: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "azuredisk-4728" for this suite.
•
------------------------------
Pre-Provisioned [single-az] 
  should fail when maxShares is invalid [disk.csi.azure.com][windows]
  /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:163
STEP: Creating a kubernetes client
May  5 08:24:59.518: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: Building a namespace api object, basename azuredisk
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
... skipping 46 lines ...
May  5 08:25:03.970: INFO: PersistentVolumeClaim pvc-tc8q5 found and phase=Bound (37.150593ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: attaching disk to node#0
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
May  5 08:25:10.847: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-bqjp8" in namespace "azuredisk-5356" to be "Succeeded or Failed"
May  5 08:25:10.884: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Pending", Reason="", readiness=false. Elapsed: 36.788573ms
May  5 08:25:12.922: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.075194016s
May  5 08:25:14.962: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.114784633s
May  5 08:25:17.000: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.153043368s
May  5 08:25:19.039: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.192272713s
May  5 08:25:21.079: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.231609243s
... skipping 23 lines ...
May  5 08:26:10.004: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Running", Reason="", readiness=true. Elapsed: 59.156800905s
May  5 08:26:12.043: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Running", Reason="", readiness=true. Elapsed: 1m1.195723526s
May  5 08:26:14.082: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Running", Reason="", readiness=true. Elapsed: 1m3.235063348s
May  5 08:26:16.121: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Running", Reason="", readiness=true. Elapsed: 1m5.273816919s
May  5 08:26:18.160: INFO: Pod "azuredisk-volume-tester-bqjp8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m7.312904887s
STEP: Saw pod success
May  5 08:26:18.160: INFO: Pod "azuredisk-volume-tester-bqjp8" satisfied condition "Succeeded or Failed"
May  5 08:26:18.160: INFO: deleting Pod "azuredisk-5356"/"azuredisk-volume-tester-bqjp8"
May  5 08:26:18.211: INFO: Pod azuredisk-volume-tester-bqjp8 has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-bqjp8 in namespace azuredisk-5356
May  5 08:26:18.349: INFO: deleting PVC "azuredisk-5356"/"pvc-tc8q5"
May  5 08:26:18.349: INFO: Deleting PersistentVolumeClaim "pvc-tc8q5"
... skipping 69 lines ...
May  5 08:26:55.138: INFO: PersistentVolumeClaim pvc-kjqh7 found and phase=Bound (4.118979554s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
May  5 08:26:55.252: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cd5pb" in namespace "azuredisk-1353" to be "Succeeded or Failed"
May  5 08:26:55.289: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 37.141715ms
May  5 08:26:57.329: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07648288s
May  5 08:26:59.366: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.113987557s
May  5 08:27:01.405: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.153070259s
May  5 08:27:03.443: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.191262267s
May  5 08:27:05.482: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.230170606s
... skipping 16 lines ...
May  5 08:27:40.145: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Pending", Reason="", readiness=false. Elapsed: 44.89247959s
May  5 08:27:42.185: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Running", Reason="", readiness=true. Elapsed: 46.933158656s
May  5 08:27:44.224: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Running", Reason="", readiness=true. Elapsed: 48.971622738s
May  5 08:27:46.263: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Running", Reason="", readiness=true. Elapsed: 51.010429557s
May  5 08:27:48.301: INFO: Pod "azuredisk-volume-tester-cd5pb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 53.049141197s
STEP: Saw pod success
May  5 08:27:48.301: INFO: Pod "azuredisk-volume-tester-cd5pb" satisfied condition "Succeeded or Failed"
May  5 08:27:48.301: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-cd5pb"
May  5 08:27:48.358: INFO: Pod azuredisk-volume-tester-cd5pb has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-cd5pb in namespace azuredisk-1353
May  5 08:27:48.404: INFO: deleting PVC "azuredisk-1353"/"pvc-kjqh7"
May  5 08:27:48.404: INFO: Deleting PersistentVolumeClaim "pvc-kjqh7"
... skipping 51 lines ...
May  5 08:29:01.881: INFO: PersistentVolumeClaim pvc-vjrvw found but phase is Pending instead of Bound.
May  5 08:29:03.920: INFO: PersistentVolumeClaim pvc-vjrvw found and phase=Bound (4.114455582s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
May  5 08:29:04.035: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-brb2s" in namespace "azuredisk-2888" to be "Succeeded or Failed"
May  5 08:29:04.072: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 37.840824ms
May  5 08:29:06.111: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076470092s
May  5 08:29:08.150: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 4.115239078s
May  5 08:29:10.188: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 6.153605422s
May  5 08:29:12.228: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 8.193015816s
May  5 08:29:14.266: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 10.230960069s
... skipping 18 lines ...
May  5 08:29:53.008: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Pending", Reason="", readiness=false. Elapsed: 48.973889681s
May  5 08:29:55.046: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Running", Reason="", readiness=true. Elapsed: 51.011800284s
May  5 08:29:57.085: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Running", Reason="", readiness=true. Elapsed: 53.049985934s
May  5 08:29:59.123: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Running", Reason="", readiness=true. Elapsed: 55.088084689s
May  5 08:30:01.161: INFO: Pod "azuredisk-volume-tester-brb2s": Phase="Succeeded", Reason="", readiness=false. Elapsed: 57.126927365s
STEP: Saw pod success
May  5 08:30:01.162: INFO: Pod "azuredisk-volume-tester-brb2s" satisfied condition "Succeeded or Failed"
May  5 08:30:01.162: INFO: deleting Pod "azuredisk-2888"/"azuredisk-volume-tester-brb2s"
May  5 08:30:01.222: INFO: Pod azuredisk-volume-tester-brb2s has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-brb2s in namespace azuredisk-2888
May  5 08:30:01.267: INFO: deleting PVC "azuredisk-2888"/"pvc-vjrvw"
May  5 08:30:01.267: INFO: Deleting PersistentVolumeClaim "pvc-vjrvw"
... skipping 46 lines ...
May  5 08:30:46.569: INFO: PersistentVolumeClaim pvc-t7mdv found and phase=Bound (4.114344707s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
May  5 08:30:46.683: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fftd2" in namespace "azuredisk-156" to be "Succeeded or Failed"
May  5 08:30:46.727: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 43.356234ms
May  5 08:30:48.766: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 2.082294959s
May  5 08:30:50.804: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 4.120422061s
May  5 08:30:52.842: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 6.158732883s
May  5 08:30:54.881: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 8.19806164s
May  5 08:30:56.919: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 10.235834713s
... skipping 16 lines ...
May  5 08:31:31.580: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Pending", Reason="", readiness=false. Elapsed: 44.896678323s
May  5 08:31:33.632: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Running", Reason="", readiness=true. Elapsed: 46.948260668s
May  5 08:31:35.670: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Running", Reason="", readiness=true. Elapsed: 48.987048555s
May  5 08:31:37.709: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Running", Reason="", readiness=true. Elapsed: 51.025311971s
May  5 08:31:39.747: INFO: Pod "azuredisk-volume-tester-fftd2": Phase="Succeeded", Reason="", readiness=false. Elapsed: 53.0632406s
STEP: Saw pod success
May  5 08:31:39.747: INFO: Pod "azuredisk-volume-tester-fftd2" satisfied condition "Succeeded or Failed"
May  5 08:31:39.747: INFO: deleting Pod "azuredisk-156"/"azuredisk-volume-tester-fftd2"
May  5 08:31:39.803: INFO: Pod azuredisk-volume-tester-fftd2 has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-fftd2 in namespace azuredisk-156
May  5 08:31:39.855: INFO: deleting PVC "azuredisk-156"/"pvc-t7mdv"
May  5 08:31:39.855: INFO: Deleting PersistentVolumeClaim "pvc-t7mdv"
... skipping 102 lines ...
May  5 08:32:26.359: INFO: PersistentVolumeClaim pvc-fjnv8 found and phase=Bound (4.113981448s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with an error
May  5 08:32:26.472: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-m2n2w" in namespace "azuredisk-9241" to be "Error status code"
May  5 08:32:26.514: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 42.303574ms
May  5 08:32:28.553: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 2.081139882s
May  5 08:32:30.591: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 4.119029086s
May  5 08:32:32.630: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 6.158162105s
May  5 08:32:34.668: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 8.196309067s
May  5 08:32:36.707: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 10.235111577s
... skipping 14 lines ...
May  5 08:33:07.288: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 40.815959634s
May  5 08:33:09.325: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 42.853386004s
May  5 08:33:11.364: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Pending", Reason="", readiness=false. Elapsed: 44.891995268s
May  5 08:33:13.402: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Running", Reason="", readiness=true. Elapsed: 46.929875671s
May  5 08:33:15.441: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Running", Reason="", readiness=true. Elapsed: 48.968677894s
May  5 08:33:17.479: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Running", Reason="", readiness=true. Elapsed: 51.007544083s
May  5 08:33:19.517: INFO: Pod "azuredisk-volume-tester-m2n2w": Phase="Failed", Reason="", readiness=false. Elapsed: 53.045498277s
STEP: Saw pod failure
May  5 08:33:19.517: INFO: Pod "azuredisk-volume-tester-m2n2w" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
May  5 08:33:19.579: INFO: deleting Pod "azuredisk-9241"/"azuredisk-volume-tester-m2n2w"
May  5 08:33:19.620: INFO: Pod azuredisk-volume-tester-m2n2w has the following logs: out-file : Access to the path 'C:\mnt\test-1\data' is denied.
At line:1 char:1
+ echo $null >> C:\mnt\test-1\data
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
... skipping 450 lines ...
May  5 08:41:06.710: INFO: PersistentVolumeClaim pvc-hbdqd found and phase=Bound (4.115241358s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
May  5 08:41:06.826: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-45csj" in namespace "azuredisk-1387" to be "Succeeded or Failed"
May  5 08:41:06.867: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 41.053063ms
May  5 08:41:08.908: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.081411038s
May  5 08:41:10.949: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.123367241s
May  5 08:41:12.989: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.163100129s
May  5 08:41:15.051: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224729481s
May  5 08:41:17.091: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.264598824s
... skipping 26 lines ...
May  5 08:42:12.140: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Pending", Reason="", readiness=false. Elapsed: 1m5.313650598s
May  5 08:42:14.179: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Running", Reason="", readiness=true. Elapsed: 1m7.352507235s
May  5 08:42:16.218: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Running", Reason="", readiness=true. Elapsed: 1m9.39207433s
May  5 08:42:18.258: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Running", Reason="", readiness=true. Elapsed: 1m11.431453032s
May  5 08:42:20.296: INFO: Pod "azuredisk-volume-tester-45csj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m13.469698692s
STEP: Saw pod success
May  5 08:42:20.296: INFO: Pod "azuredisk-volume-tester-45csj" satisfied condition "Succeeded or Failed"
May  5 08:42:20.296: INFO: deleting Pod "azuredisk-1387"/"azuredisk-volume-tester-45csj"
May  5 08:42:20.359: INFO: Pod azuredisk-volume-tester-45csj has the following logs: hello world
hello world
hello world

STEP: Deleting pod azuredisk-volume-tester-45csj in namespace azuredisk-1387
... skipping 181 lines ...
May  5 08:44:04.777: INFO: PersistentVolumeClaim pvc-xvjz4 found but phase is Pending instead of Bound.
May  5 08:44:06.816: INFO: PersistentVolumeClaim pvc-xvjz4 found and phase=Bound (4.114816187s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
May  5 08:44:06.941: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jgpsz" in namespace "azuredisk-7578" to be "Succeeded or Failed"
May  5 08:44:06.983: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 41.702257ms
May  5 08:44:09.022: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.080747288s
May  5 08:44:11.062: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.120525916s
May  5 08:44:13.102: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.160165699s
May  5 08:44:15.141: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.19954058s
May  5 08:44:17.179: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.237978833s
... skipping 25 lines ...
May  5 08:45:10.194: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Pending", Reason="", readiness=false. Elapsed: 1m3.252298888s
May  5 08:45:12.232: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Running", Reason="", readiness=true. Elapsed: 1m5.290350042s
May  5 08:45:14.270: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Running", Reason="", readiness=true. Elapsed: 1m7.328924441s
May  5 08:45:16.309: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Running", Reason="", readiness=true. Elapsed: 1m9.367670641s
May  5 08:45:18.349: INFO: Pod "azuredisk-volume-tester-jgpsz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m11.407207013s
STEP: Saw pod success
May  5 08:45:18.349: INFO: Pod "azuredisk-volume-tester-jgpsz" satisfied condition "Succeeded or Failed"
May  5 08:45:18.349: INFO: deleting Pod "azuredisk-7578"/"azuredisk-volume-tester-jgpsz"
May  5 08:45:18.411: INFO: Pod azuredisk-volume-tester-jgpsz has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-jgpsz in namespace azuredisk-7578
May  5 08:45:18.455: INFO: deleting PVC "azuredisk-7578"/"pvc-xvjz4"
May  5 08:45:18.455: INFO: Deleting PersistentVolumeClaim "pvc-xvjz4"
... skipping 516 lines ...
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0505 08:10:29.881030       1 azuredisk.go:168] driver userAgent: disk.csi.azure.com/v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b gc/go1.18.1 (amd64-linux) e2e-test
I0505 08:10:29.881587       1 azure_disk_utils.go:159] reading cloud config from secret kube-system/azure-cloud-provider
I0505 08:10:29.897235       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 15 milliseconds
W0505 08:10:29.897585       1 azure_disk_utils.go:166] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0505 08:10:29.897604       1 azure_disk_utils.go:171] could not read cloud config from secret kube-system/azure-cloud-provider
I0505 08:10:29.897614       1 azure_disk_utils.go:181] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0505 08:10:29.897734       1 azure_disk_utils.go:189] read cloud config from file: /etc/kubernetes/azure.json successfully
I0505 08:10:29.898311       1 azure_auth.go:245] Using AzurePublicCloud environment
I0505 08:10:29.898358       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0505 08:10:29.898434       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 258 lines ...
I0505 08:25:26.875544       1 azure_controller_common.go:365] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded
I0505 08:25:26.875568       1 controllerserver.go:398] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-nqwf-qb4nr again
I0505 08:25:26.875585       1 azure_vmss_cache.go:332] Node capz-nqwf-qb4nr has joined the cluster since the last VM cache refresh, refreshing the cache
I0505 08:25:26.940785       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.065158098 request="vm_list" resource_group="capz-nqwflh" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I0505 08:25:26.940819       1 azure_backoff.go:101] VirtualMachinesClient.List(capz-nqwflh) success
I0505 08:25:26.940863       1 azure_controller_common.go:174] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-nqwf-mbpbk, could not be attached to node(capz-nqwf-qb4nr)
E0505 08:25:26.940883       1 controllerserver.go:402] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-nqwf-qb4nr failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/virtualMachines/capz-nqwf-mbpbk), could not be attached to node(capz-nqwf-qb4nr)
I0505 08:25:26.940934       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=15.935000111 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-nqwflh" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="capz-nqwf-qb4nr" result_code="failed"
E0505 08:25:26.940955       1 utils.go:82] GRPC error: Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-nqwf-qb4nr failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/virtualMachines/capz-nqwf-mbpbk), could not be attached to node(capz-nqwf-qb4nr)
I0505 08:25:26.949611       1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0505 08:25:26.949635       1 utils.go:78] GRPC request: {"node_id":"capz-nqwf-qb4nr","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":7}},"volume_context":{"cachingMode":"None","requestedsizegib":"10","skuName":"Premium_LRS"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"}
I0505 08:25:26.984090       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.03429412 request="disks_get" resource_group="capz-nqwflh" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I0505 08:25:26.984144       1 controllerserver.go:355] GetDiskLun returned: <nil>. Initiating attaching volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-nqwf-qb4nr.
I0505 08:25:26.984162       1 azure_vmss_cache.go:332] Node capz-nqwf-qb4nr has joined the cluster since the last VM cache refresh, refreshing the cache
I0505 08:25:27.032197       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.047989788 request="vm_list" resource_group="capz-nqwflh" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
... skipping 166 lines ...
I0505 08:28:56.800825       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=5.323766318 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-nqwflh" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-nqwflh/providers/Microsoft.Compute/disks/pvc-66be74dd-b938-4aca-9017-c77aabab5d2b" result_code="succeeded"
I0505 08:28:56.800845       1 utils.go:84] GRPC response: {}
I0505 08:28:59.800396       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I0505 08:28:59.800869       1 utils.go:78] GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.disk.csi.azure.com/zone":""}}],"requisite":[{"segments":{"topology.disk.csi.azure.com/zone":""}}]},"capacity_range":{"required_bytes":10737418240},"name":"pvc-04652351-1f88-400a-ae4e-947061021d0b","parameters":{"csi.storage.k8s.io/pv/name":"pvc-04652351-1f88-400a-ae4e-947061021d0b","csi.storage.k8s.io/pvc/name":"pvc-vjrvw","csi.storage.k8s.io/pvc/namespace":"azuredisk-2888","enableAsyncAttach":"false","networkAccessPolicy":"DenyAll","skuName":"Standard_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]}
I0505 08:28:59.801632       1 azure_disk_utils.go:159] reading cloud config from secret kube-system/azure-cloud-provider
I0505 08:28:59.816689       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 14 milliseconds
W0505 08:28:59.817083       1 azure_disk_utils.go:166] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0505 08:28:59.817100       1 azure_disk_utils.go:171] could not read cloud config from secret kube-system/azure-cloud-provider
I0505 08:28:59.817112       1 azure_disk_utils.go:181] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0505 08:28:59.817153       1 azure_disk_utils.go:189] read cloud config from file: /etc/kubernetes/azure.json successfully
I0505 08:28:59.817388       1 azure_auth.go:245] Using AzurePublicCloud environment
I0505 08:28:59.817433       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0505 08:28:59.817481       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 82 lines ...
I0505 08:30:41.137811       1 utils.go:78] GRPC request: {}
I0505 08:30:41.137868       1 utils.go:84] GRPC response: {"ready":{"value":true}}
I0505 08:30:42.452386       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I0505 08:30:42.452648       1 utils.go:78] GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.disk.csi.azure.com/zone":""}}],"requisite":[{"segments":{"topology.disk.csi.azure.com/zone":""}}]},"capacity_range":{"required_bytes":1099511627776},"name":"pvc-79378a62-fcc7-4223-b280-4213df8d2e14","parameters":{"csi.storage.k8s.io/pv/name":"pvc-79378a62-fcc7-4223-b280-4213df8d2e14","csi.storage.k8s.io/pvc/name":"pvc-t7mdv","csi.storage.k8s.io/pvc/namespace":"azuredisk-156","enableAsyncAttach":"false","enableBursting":"true","perfProfile":"Basic","skuName":"Premium_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]}
I0505 08:30:42.453631       1 azure_disk_utils.go:159] reading cloud config from secret kube-system/azure-cloud-provider
I0505 08:30:42.461569       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 7 milliseconds
W0505 08:30:42.461733       1 azure_disk_utils.go:166] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0505 08:30:42.461770       1 azure_disk_utils.go:171] could not read cloud config from secret kube-system/azure-cloud-provider
I0505 08:30:42.461780       1 azure_disk_utils.go:181] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0505 08:30:42.461840       1 azure_disk_utils.go:189] read cloud config from file: /etc/kubernetes/azure.json successfully
I0505 08:30:42.462071       1 azure_auth.go:245] Using AzurePublicCloud environment
I0505 08:30:42.462117       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0505 08:30:42.462164       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 1684 lines ...
Go Version: go1.18.1
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0505 08:10:39.604431    1552 azuredisk.go:168] driver userAgent: disk.csi.azure.com/v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b gc/go1.18.1 (amd64-windows) e2e-test
W0505 08:10:39.606393    1552 azure_disk_utils.go:227] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified.
I0505 08:10:39.606615    1552 azure_disk_utils.go:171] could not read cloud config from secret kube-system/azure-cloud-provider
I0505 08:10:39.606615    1552 azure_disk_utils.go:181] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0505 08:10:39.606615    1552 azure_disk_utils.go:189] read cloud config from file: C:\k\azure.json successfully
I0505 08:10:39.608492    1552 azure_auth.go:245] Using AzurePublicCloud environment
I0505 08:10:39.609068    1552 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0505 08:10:39.610172    1552 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 19 lines ...
I0505 08:10:39.850519    1552 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b"}
I0505 08:10:39.966198    1552 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0505 08:10:39.966198    1552 utils.go:78] GRPC request: {}
I0505 08:10:39.966198    1552 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b"}
I0505 08:10:40.210094    1552 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I0505 08:10:40.210133    1552 utils.go:78] GRPC request: {}
I0505 08:10:40.230474    1552 azure_instance_metadata.go:138] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I0505 08:10:40.236244    1552 nodeserver.go:372] NodeGetInfo: nodeName(capz-nqwf-qb4nr), VM Size(Standard_D4s_v3)
I0505 08:10:40.236244    1552 nodeserver.go:410] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I0505 08:10:40.236244    1552 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-nqwf-qb4nr"}
I0505 08:10:58.517727    1552 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0505 08:10:58.517727    1552 utils.go:78] GRPC request: {}
I0505 08:10:58.517727    1552 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
... skipping 1351 lines ...
Go Version: go1.18.1
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0505 08:10:40.870103    5768 azuredisk.go:168] driver userAgent: disk.csi.azure.com/v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b gc/go1.18.1 (amd64-windows) e2e-test
W0505 08:10:40.872682    5768 azure_disk_utils.go:227] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified.
I0505 08:10:40.872682    5768 azure_disk_utils.go:171] could not read cloud config from secret kube-system/azure-cloud-provider
I0505 08:10:40.872682    5768 azure_disk_utils.go:181] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0505 08:10:40.872682    5768 azure_disk_utils.go:189] read cloud config from file: C:\k\azure.json successfully
I0505 08:10:40.874657    5768 azure_auth.go:245] Using AzurePublicCloud environment
I0505 08:10:40.874657    5768 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0505 08:10:40.876453    5768 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 19 lines ...
I0505 08:10:41.083110    5768 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b"}
I0505 08:10:41.148336    5768 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0505 08:10:41.148336    5768 utils.go:78] GRPC request: {}
I0505 08:10:41.148336    5768 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.18.0-4d0016a42e8322c34e24b5663e71e1e536f02c7b"}
I0505 08:10:41.477431    5768 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I0505 08:10:41.477431    5768 utils.go:78] GRPC request: {}
I0505 08:10:41.502979    5768 azure_instance_metadata.go:138] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I0505 08:10:41.502979    5768 nodeserver.go:372] NodeGetInfo: nodeName(capz-nqwf-mbpbk), VM Size(Standard_D4s_v3)
I0505 08:10:41.502979    5768 nodeserver.go:410] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I0505 08:10:41.502979    5768 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-nqwf-mbpbk"}
I0505 08:11:11.099699    5768 utils.go:77] GRPC call: /csi.v1.Identity/Probe
I0505 08:11:11.099699    5768 utils.go:78] GRPC request: {}
I0505 08:11:11.099699    5768 utils.go:84] GRPC response: {"ready":{"value":true}}
... skipping 536 lines ...
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 31
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 31
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 31
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 31
cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 451.61655907500005
cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 31
# HELP cloudprovider_azure_op_failure_count [ALPHA] Number of failed Azure service operations
# TYPE cloudprovider_azure_op_failure_count counter
cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-nqwflh",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1
# HELP go_gc_duration_seconds A summary of the pause duration of garbage collection cycles.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 2.3601e-05
go_gc_duration_seconds{quantile="0.25"} 5.32e-05
... skipping 197 lines ...

JUnit report was created: /logs/artifacts/junit_01.xml


Summarizing 1 Failure:

[Fail] Pre-Provisioned [single-az] [It] should use a pre-provisioned volume and mount it as readOnly in a pod [disk.csi.azure.com][windows] 
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/pre_provisioned_read_only_volume_tester.go:60

Ran 19 of 59 Specs in 3570.765 seconds
FAIL! -- 18 Passed | 1 Failed | 0 Pending | 40 Skipped

You're using deprecated Ginkgo functionality:
=============================================
Ginkgo 2.0 is under active development and will introduce several new features, improvements, and a small handful of breaking changes.
A release candidate for 2.0 is now available and 2.0 should GA in Fall 2021.  Please give the RC a try and send us feedback!
  - To learn more, view the migration guide at https://github.com/onsi/ginkgo/blob/ver2/docs/MIGRATING_TO_V2.md
... skipping 5 lines ...
  If this change will be impactful to you please leave a comment on https://github.com/onsi/ginkgo/issues/711
  Learn more at: https://github.com/onsi/ginkgo/blob/ver2/docs/MIGRATING_TO_V2.md#removed-custom-reporters

To silence deprecations that can be silenced set the following environment variable:
  ACK_GINKGO_DEPRECATIONS=1.16.5

--- FAIL: TestE2E (3570.79s)
FAIL
FAIL	sigs.k8s.io/azuredisk-csi-driver/test/e2e	3570.838s
FAIL
make: *** [Makefile:260: e2e-test] Error 1
make: Nothing to be done for 'kubectl'.
================ DUMPING LOGS FOR MANAGEMENT CLUSTER ================
Exported logs for cluster "capz" to:
/logs/artifacts/management-cluster
================ DUMPING LOGS FOR WORKLOAD CLUSTER (Linux) ==========
Deploying log-dump-daemonset
... skipping 90 lines ...