This job view page is being replaced by Spyglass soon. Check out the new job view.
PRandyzhangx: test: support Win2022 test on capz
ResultFAILURE
Tests 1 failed / 18 succeeded
Started2022-04-14 05:31
Elapsed1h16m
Revisiond7600c07bbfa811ac4d88920710966de02038df5
Refs 1280

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] 14m32s

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 580 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 1063 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 123 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
W0414 05:50:11.565715   36529 azure_disk_utils.go:165] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
W0414 05:50:11.566450   36529 azuredisk.go:185] DisableAvailabilitySetNodes for controller is set as false while current VMType is vmss
I0414 05:50:11.566787   36529 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME
I0414 05:50:11.566802   36529 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0414 05:50:11.566806   36529 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0414 05:50:11.566810   36529 driver.go:81] Enabling controller service capability: CLONE_VOLUME
I0414 05:50:11.566814   36529 driver.go:81] Enabling controller service capability: EXPAND_VOLUME
... skipping 18 lines ...
Apr 14 05:50:16.205: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-8kjzt] to have phase Bound
Apr 14 05:50:16.236: INFO: PersistentVolumeClaim pvc-8kjzt found and phase=Bound (31.173678ms)
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
Apr 14 05:50:16.341: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-59m9v" in namespace "azuredisk-8081" to be "Error status code"
Apr 14 05:50:16.373: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 31.314533ms
Apr 14 05:50:18.407: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065473085s
Apr 14 05:50:20.440: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098641056s
Apr 14 05:50:22.473: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 6.131598856s
Apr 14 05:50:24.506: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 8.16471948s
Apr 14 05:50:26.539: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 10.198064844s
... skipping 225 lines ...
Apr 14 05:58:06.320: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m49.978724284s
Apr 14 05:58:08.354: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m52.013244083s
Apr 14 05:58:10.391: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m54.049795304s
Apr 14 05:58:12.426: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m56.084415753s
Apr 14 05:58:14.461: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m58.11958215s
Apr 14 05:58:16.496: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Pending", Reason="", readiness=false. Elapsed: 8m0.154406163s
Apr 14 05:58:18.530: INFO: Pod "azuredisk-volume-tester-59m9v": Phase="Failed", Reason="", readiness=false. Elapsed: 8m2.188313003s
STEP: Saw pod failure
Apr 14 05:58:18.530: INFO: Pod "azuredisk-volume-tester-59m9v" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 14 05:58:18.625: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-59m9v"
Apr 14 05:58:18.661: INFO: Pod azuredisk-volume-tester-59m9v has the following logs: 
STEP: Deleting pod azuredisk-volume-tester-59m9v in namespace azuredisk-8081
Apr 14 05:58:18.709: INFO: deleting PVC "azuredisk-8081"/"pvc-8kjzt"
Apr 14 05:58:18.709: INFO: Deleting PersistentVolumeClaim "pvc-8kjzt"
... skipping 83 lines ...
STEP: Found 10 events.
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:50:16 +0000 UTC - event for azuredisk-volume-tester-59m9v: {default-scheduler } Scheduled: Successfully assigned azuredisk-8081/azuredisk-volume-tester-59m9v to capz-0my2-bps4g
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:50:27 +0000 UTC - event for azuredisk-volume-tester-59m9v: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "azuredisk-8081-disk.csi.azure.com-preprovisioned-pv-txt7c" 
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:51:09 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:56:15 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 5m6.114301s
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:56:16 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Created: Created container volume-tester
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:58:16 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Failed: Error: context deadline exceeded
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:58:16 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:58:22 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Started: Started container volume-tester
Apr 14 06:04:36.408: INFO: At 2022-04-14 05:58:22 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} Killing: Stopping container volume-tester
Apr 14 06:04:36.408: INFO: At 2022-04-14 06:00:24 +0000 UTC - event for azuredisk-volume-tester-59m9v: {kubelet capz-0my2-bps4g} FailedKillPod: error killing pod: failed to "KillPodSandbox" for "6b93ade4-7c36-4244-87b5-62fa24c3cb74" with KillPodSandboxError: "rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Apr 14 06:04:36.440: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 14 06:04:36.440: INFO: 
Apr 14 06:04:36.493: INFO: 
Logging node info for node capz-0my2-9g9mh
Apr 14 06:04:36.526: INFO: Node Info: &Node{ObjectMeta:{capz-0my2-9g9mh    e6c2c881-81bf-4a4e-91b7-f643fc534384 3455 0 2022-04-14 05:45:35 +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-0my2-9g9mh 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-0my2ur cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-0my2ur-md-win-6ff4948587-fl85c cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-0my2ur-md-win-6ff4948587 csi.volume.kubernetes.io/nodeid:{"disk.csi.azure.com":"capz-0my2-9g9mh"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.4/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.31.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:94:fa:7f volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-14 05:45:36 +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-04-14 05:45:40 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-14 05:45:51 +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-04-14 05:47:06 +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-04-14 05:50:09 +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-0my2ur/providers/Microsoft.Compute/virtualMachines/capz-0my2-9g9mh,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-04-14 06:00:56 +0000 UTC,LastTransitionTime:2022-04-14 05:45:35 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-14 06:00:56 +0000 UTC,LastTransitionTime:2022-04-14 05:45:35 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-14 06:00:56 +0000 UTC,LastTransitionTime:2022-04-14 05:45:35 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-14 06:00:56 +0000 UTC,LastTransitionTime:2022-04-14 05:46:37 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-0my2-9g9mh,},NodeAddress{Type:InternalIP,Address:10.1.0.4,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-0my2-9g9mh,SystemUUID:A4AB906F-0DD6-4BE9-86F6-F072B9AB1488,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:[capzci.azurecr.io/azuredisk-csi@sha256:9696ebf523bc8984cc428881c99497cfc9108804764f335edd6839b955a4c152 capzci.azurecr.io/azuredisk-csi:v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f],SizeBytes:141766005,},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:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},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,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
Apr 14 06:04:36.527: INFO: 
... skipping 188 lines ...
  [single-az]
  /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:69
    should succeed when creating a shared disk [disk.csi.azure.com][windows]
    /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:143
------------------------------
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
Apr 14 06:05:03.710: 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 ...
Apr 14 06:05:07.595: INFO: PersistentVolumeClaim pvc-t27tq found and phase=Bound (33.650108ms)
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
Apr 14 06:05:19.357: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qvdcc" in namespace "azuredisk-5356" to be "Succeeded or Failed"
Apr 14 06:05:19.389: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Pending", Reason="", readiness=false. Elapsed: 32.088351ms
Apr 14 06:05:21.421: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06436916s
Apr 14 06:05:23.456: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098577935s
Apr 14 06:05:25.491: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.134300847s
Apr 14 06:05:27.528: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.170777186s
Apr 14 06:05:29.560: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.203248675s
... skipping 34 lines ...
Apr 14 06:06:40.870: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Running", Reason="", readiness=true. Elapsed: 1m21.513302763s
Apr 14 06:06:42.903: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Running", Reason="", readiness=true. Elapsed: 1m23.546059453s
Apr 14 06:06:44.936: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Running", Reason="", readiness=true. Elapsed: 1m25.578732322s
Apr 14 06:06:46.970: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Running", Reason="", readiness=true. Elapsed: 1m27.6125603s
Apr 14 06:06:49.002: INFO: Pod "azuredisk-volume-tester-qvdcc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m29.645155202s
STEP: Saw pod success
Apr 14 06:06:49.002: INFO: Pod "azuredisk-volume-tester-qvdcc" satisfied condition "Succeeded or Failed"
Apr 14 06:06:49.002: INFO: deleting Pod "azuredisk-5356"/"azuredisk-volume-tester-qvdcc"
Apr 14 06:06:49.053: INFO: Pod azuredisk-volume-tester-qvdcc has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-qvdcc in namespace azuredisk-5356
Apr 14 06:06:49.210: INFO: deleting PVC "azuredisk-5356"/"pvc-t27tq"
Apr 14 06:06:49.210: INFO: Deleting PersistentVolumeClaim "pvc-t27tq"
... skipping 68 lines ...
Apr 14 06:07:25.908: INFO: PersistentVolumeClaim pvc-pjpg9 found and phase=Bound (4.125878184s)
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
Apr 14 06:07:26.004: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6bhlv" in namespace "azuredisk-1353" to be "Succeeded or Failed"
Apr 14 06:07:26.038: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 33.681793ms
Apr 14 06:07:28.070: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065506475s
Apr 14 06:07:30.103: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098339487s
Apr 14 06:07:32.135: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.130687675s
Apr 14 06:07:34.169: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.164411698s
Apr 14 06:07:36.202: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.197705143s
... skipping 16 lines ...
Apr 14 06:08:10.761: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Pending", Reason="", readiness=false. Elapsed: 44.756106469s
Apr 14 06:08:12.793: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Running", Reason="", readiness=true. Elapsed: 46.788610442s
Apr 14 06:08:14.827: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Running", Reason="", readiness=true. Elapsed: 48.822062186s
Apr 14 06:08:16.859: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Running", Reason="", readiness=true. Elapsed: 50.854845921s
Apr 14 06:08:18.892: INFO: Pod "azuredisk-volume-tester-6bhlv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 52.887982244s
STEP: Saw pod success
Apr 14 06:08:18.893: INFO: Pod "azuredisk-volume-tester-6bhlv" satisfied condition "Succeeded or Failed"
Apr 14 06:08:18.893: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-6bhlv"
Apr 14 06:08:18.936: INFO: Pod azuredisk-volume-tester-6bhlv has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-6bhlv in namespace azuredisk-1353
Apr 14 06:08:18.976: INFO: deleting PVC "azuredisk-1353"/"pvc-pjpg9"
Apr 14 06:08:18.976: INFO: Deleting PersistentVolumeClaim "pvc-pjpg9"
... skipping 45 lines ...
Apr 14 06:09:02.090: INFO: PersistentVolumeClaim pvc-65j9w found but phase is Pending instead of Bound.
Apr 14 06:09:04.126: INFO: PersistentVolumeClaim pvc-65j9w found and phase=Bound (4.100797467s)
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
Apr 14 06:09:04.223: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rrgxc" in namespace "azuredisk-2888" to be "Succeeded or Failed"
Apr 14 06:09:04.264: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 40.287886ms
Apr 14 06:09:06.297: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.073664219s
Apr 14 06:09:08.329: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.105767422s
Apr 14 06:09:10.364: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.140380002s
Apr 14 06:09:12.396: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.173029758s
Apr 14 06:09:14.429: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205338826s
... skipping 21 lines ...
Apr 14 06:09:59.151: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Pending", Reason="", readiness=false. Elapsed: 54.927638097s
Apr 14 06:10:01.184: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Running", Reason="", readiness=true. Elapsed: 56.960441641s
Apr 14 06:10:03.217: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Running", Reason="", readiness=true. Elapsed: 58.993320793s
Apr 14 06:10:05.250: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Running", Reason="", readiness=true. Elapsed: 1m1.027018335s
Apr 14 06:10:07.283: INFO: Pod "azuredisk-volume-tester-rrgxc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m3.059605227s
STEP: Saw pod success
Apr 14 06:10:07.283: INFO: Pod "azuredisk-volume-tester-rrgxc" satisfied condition "Succeeded or Failed"
Apr 14 06:10:07.283: INFO: deleting Pod "azuredisk-2888"/"azuredisk-volume-tester-rrgxc"
Apr 14 06:10:07.340: INFO: Pod azuredisk-volume-tester-rrgxc has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-rrgxc in namespace azuredisk-2888
Apr 14 06:10:07.382: INFO: deleting PVC "azuredisk-2888"/"pvc-65j9w"
Apr 14 06:10:07.382: INFO: Deleting PersistentVolumeClaim "pvc-65j9w"
... skipping 46 lines ...
Apr 14 06:10:52.534: INFO: PersistentVolumeClaim pvc-442hn found and phase=Bound (4.094928157s)
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
Apr 14 06:10:52.630: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rhr4n" in namespace "azuredisk-156" to be "Succeeded or Failed"
Apr 14 06:10:52.665: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 35.043562ms
Apr 14 06:10:54.697: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06729791s
Apr 14 06:10:56.730: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 4.099874228s
Apr 14 06:10:58.763: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132829321s
Apr 14 06:11:00.798: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 8.168408915s
Apr 14 06:11:02.830: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 10.200565087s
... skipping 16 lines ...
Apr 14 06:11:37.400: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Pending", Reason="", readiness=false. Elapsed: 44.770016187s
Apr 14 06:11:39.432: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Running", Reason="", readiness=true. Elapsed: 46.802173294s
Apr 14 06:11:41.465: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Running", Reason="", readiness=true. Elapsed: 48.834874626s
Apr 14 06:11:43.499: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Running", Reason="", readiness=true. Elapsed: 50.868881165s
Apr 14 06:11:45.532: INFO: Pod "azuredisk-volume-tester-rhr4n": Phase="Succeeded", Reason="", readiness=false. Elapsed: 52.902353172s
STEP: Saw pod success
Apr 14 06:11:45.532: INFO: Pod "azuredisk-volume-tester-rhr4n" satisfied condition "Succeeded or Failed"
Apr 14 06:11:45.532: INFO: deleting Pod "azuredisk-156"/"azuredisk-volume-tester-rhr4n"
Apr 14 06:11:45.582: INFO: Pod azuredisk-volume-tester-rhr4n has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-rhr4n in namespace azuredisk-156
Apr 14 06:11:45.620: INFO: deleting PVC "azuredisk-156"/"pvc-442hn"
Apr 14 06:11:45.620: INFO: Deleting PersistentVolumeClaim "pvc-442hn"
... skipping 102 lines ...
Apr 14 06:12:31.985: INFO: PersistentVolumeClaim pvc-zslzq found and phase=Bound (4.102961993s)
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
Apr 14 06:12:32.081: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-8zpvm" in namespace "azuredisk-9241" to be "Error status code"
Apr 14 06:12:32.113: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 32.703372ms
Apr 14 06:12:34.145: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064655249s
Apr 14 06:12:36.177: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.09666045s
Apr 14 06:12:38.210: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.12936094s
Apr 14 06:12:40.243: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.161940385s
Apr 14 06:12:42.284: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 10.203451489s
... skipping 19 lines ...
Apr 14 06:13:22.949: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 50.868768058s
Apr 14 06:13:24.983: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 52.902569783s
Apr 14 06:13:27.019: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Pending", Reason="", readiness=false. Elapsed: 54.938354811s
Apr 14 06:13:29.052: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Running", Reason="", readiness=true. Elapsed: 56.970853617s
Apr 14 06:13:31.084: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Running", Reason="", readiness=true. Elapsed: 59.003736789s
Apr 14 06:13:33.118: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Running", Reason="", readiness=true. Elapsed: 1m1.037508575s
Apr 14 06:13:35.152: INFO: Pod "azuredisk-volume-tester-8zpvm": Phase="Failed", Reason="", readiness=false. Elapsed: 1m3.071298106s
STEP: Saw pod failure
Apr 14 06:13:35.152: INFO: Pod "azuredisk-volume-tester-8zpvm" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 14 06:13:35.205: INFO: deleting Pod "azuredisk-9241"/"azuredisk-volume-tester-8zpvm"
Apr 14 06:13:35.243: INFO: Pod azuredisk-volume-tester-8zpvm 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 455 lines ...
Apr 14 06:22:02.119: INFO: PersistentVolumeClaim pvc-85tm6 found and phase=Bound (4.09577241s)
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
Apr 14 06:22:02.221: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-r5pjc" in namespace "azuredisk-1387" to be "Succeeded or Failed"
Apr 14 06:22:02.252: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 31.466216ms
Apr 14 06:22:04.287: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066198575s
Apr 14 06:22:06.320: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.09881942s
Apr 14 06:22:08.353: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.131899089s
Apr 14 06:22:10.388: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167253008s
Apr 14 06:22:12.421: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.199914719s
... skipping 27 lines ...
Apr 14 06:23:09.357: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Pending", Reason="", readiness=false. Elapsed: 1m7.136351213s
Apr 14 06:23:11.391: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Running", Reason="", readiness=true. Elapsed: 1m9.169830211s
Apr 14 06:23:13.424: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Running", Reason="", readiness=true. Elapsed: 1m11.20266673s
Apr 14 06:23:15.457: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Running", Reason="", readiness=true. Elapsed: 1m13.236324632s
Apr 14 06:23:17.490: INFO: Pod "azuredisk-volume-tester-r5pjc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m15.26922765s
STEP: Saw pod success
Apr 14 06:23:17.490: INFO: Pod "azuredisk-volume-tester-r5pjc" satisfied condition "Succeeded or Failed"
Apr 14 06:23:17.490: INFO: deleting Pod "azuredisk-1387"/"azuredisk-volume-tester-r5pjc"
Apr 14 06:23:17.545: INFO: Pod azuredisk-volume-tester-r5pjc has the following logs: hello world
hello world
hello world

STEP: Deleting pod azuredisk-volume-tester-r5pjc in namespace azuredisk-1387
... skipping 181 lines ...
Apr 14 06:25:01.426: INFO: PersistentVolumeClaim pvc-mgb6k found but phase is Pending instead of Bound.
Apr 14 06:25:03.458: INFO: PersistentVolumeClaim pvc-mgb6k found and phase=Bound (4.09651231s)
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
Apr 14 06:25:03.554: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gsgpr" in namespace "azuredisk-7578" to be "Succeeded or Failed"
Apr 14 06:25:03.588: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Pending", Reason="", readiness=false. Elapsed: 33.918297ms
Apr 14 06:25:05.621: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06688093s
Apr 14 06:25:07.654: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.100264349s
Apr 14 06:25:09.687: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132837374s
Apr 14 06:25:11.720: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166229494s
Apr 14 06:25:13.753: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.199140551s
... skipping 28 lines ...
Apr 14 06:26:12.721: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Running", Reason="", readiness=true. Elapsed: 1m9.166802212s
Apr 14 06:26:14.754: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Running", Reason="", readiness=true. Elapsed: 1m11.199726998s
Apr 14 06:26:16.788: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Running", Reason="", readiness=true. Elapsed: 1m13.233491505s
Apr 14 06:26:18.820: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Running", Reason="", readiness=true. Elapsed: 1m15.266284811s
Apr 14 06:26:20.855: INFO: Pod "azuredisk-volume-tester-gsgpr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m17.30058886s
STEP: Saw pod success
Apr 14 06:26:20.855: INFO: Pod "azuredisk-volume-tester-gsgpr" satisfied condition "Succeeded or Failed"
Apr 14 06:26:20.855: INFO: deleting Pod "azuredisk-7578"/"azuredisk-volume-tester-gsgpr"
Apr 14 06:26:20.905: INFO: Pod azuredisk-volume-tester-gsgpr has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-gsgpr in namespace azuredisk-7578
Apr 14 06:26:20.961: INFO: deleting PVC "azuredisk-7578"/"pvc-mgb6k"
Apr 14 06:26:20.961: INFO: Deleting PersistentVolumeClaim "pvc-mgb6k"
... skipping 523 lines ...
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0414 05:49:31.469975       1 azuredisk.go:165] driver userAgent: disk.csi.azure.com/v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f gc/go1.18 (amd64-linux) e2e-test
I0414 05:49:31.470403       1 azure_disk_utils.go:158] reading cloud config from secret kube-system/azure-cloud-provider
I0414 05:49:31.486347       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
W0414 05:49:31.486559       1 azure_disk_utils.go:165] 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
I0414 05:49:31.486588       1 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0414 05:49:31.486601       1 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0414 05:49:31.486640       1 azure_disk_utils.go:188] read cloud config from file: /etc/kubernetes/azure.json successfully
I0414 05:49:31.487197       1 azure_auth.go:245] Using AzurePublicCloud environment
I0414 05:49:31.487255       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0414 05:49:31.487322       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 247 lines ...
I0414 06:05:40.663109       1 azure_controller_common.go:365] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded
I0414 06:05:40.663139       1 controllerserver.go:393] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-0my2-bps4g again
I0414 06:05:40.663156       1 azure_vmss_cache.go:332] Node capz-0my2-bps4g has joined the cluster since the last VM cache refresh, refreshing the cache
I0414 06:05:40.738260       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.075054996 request="vm_list" resource_group="capz-0my2ur" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I0414 06:05:40.738300       1 azure_backoff.go:101] VirtualMachinesClient.List(capz-0my2ur) success
I0414 06:05:40.738360       1 azure_controller_common.go:174] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-0my2-9g9mh, could not be attached to node(capz-0my2-bps4g)
E0414 06:05:40.738396       1 controllerserver.go:397] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-0my2-bps4g failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/virtualMachines/capz-0my2-9g9mh), could not be attached to node(capz-0my2-bps4g)
I0414 06:05:40.738479       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=21.285842889 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-0my2ur" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes=capz-0my2-bps4g result_code="failed"
E0414 06:05:40.738507       1 utils.go:82] GRPC error: Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-0my2-bps4g failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/virtualMachines/capz-0my2-9g9mh), could not be attached to node(capz-0my2-bps4g)
I0414 06:05:40.743700       1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0414 06:05:40.743727       1 utils.go:78] GRPC request: {"node_id":"capz-0my2-bps4g","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-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"}
I0414 06:05:40.772782       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.028863344 request="disks_get" resource_group="capz-0my2ur" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I0414 06:05:40.772853       1 controllerserver.go:350] GetDiskLun returned: <nil>. Initiating attaching volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-0my2-bps4g.
I0414 06:05:40.772898       1 azure_vmss_cache.go:332] Node capz-0my2-bps4g has joined the cluster since the last VM cache refresh, refreshing the cache
I0414 06:05:40.817412       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.044470812 request="vm_list" resource_group="capz-0my2ur" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
... skipping 114 lines ...
I0414 06:08:55.226588       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=5.210771549 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-0my2ur" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/pvc-f38c8eb6-ec7f-4454-aada-b3f180046326="" result_code="succeeded"
I0414 06:08:55.226608       1 utils.go:84] GRPC response: {}
I0414 06:09:00.018914       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I0414 06:09:00.018946       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-558d88ca-e949-4e57-8b83-13bd182cb3af","parameters":{"csi.storage.k8s.io/pv/name":"pvc-558d88ca-e949-4e57-8b83-13bd182cb3af","csi.storage.k8s.io/pvc/name":"pvc-65j9w","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}}]}
I0414 06:09:00.019527       1 azure_disk_utils.go:158] reading cloud config from secret kube-system/azure-cloud-provider
I0414 06:09:00.031072       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 11 milliseconds
W0414 06:09:00.031220       1 azure_disk_utils.go:165] 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
I0414 06:09:00.031238       1 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0414 06:09:00.031250       1 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0414 06:09:00.031305       1 azure_disk_utils.go:188] read cloud config from file: /etc/kubernetes/azure.json successfully
I0414 06:09:00.031511       1 azure_auth.go:245] Using AzurePublicCloud environment
I0414 06:09:00.031568       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0414 06:09:00.031607       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 71 lines ...
I0414 06:10:43.647891       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=5.221826355 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-0my2ur" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-0my2ur/providers/Microsoft.Compute/disks/pvc-558d88ca-e949-4e57-8b83-13bd182cb3af="" result_code="succeeded"
I0414 06:10:43.647911       1 utils.go:84] GRPC response: {}
I0414 06:10:48.432523       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I0414 06:10:48.432551       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-240d4444-f122-453d-ad96-bf54657d0e6e","parameters":{"csi.storage.k8s.io/pv/name":"pvc-240d4444-f122-453d-ad96-bf54657d0e6e","csi.storage.k8s.io/pvc/name":"pvc-442hn","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}}]}
I0414 06:10:48.433018       1 azure_disk_utils.go:158] reading cloud config from secret kube-system/azure-cloud-provider
I0414 06:10:48.442956       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 9 milliseconds
W0414 06:10:48.443061       1 azure_disk_utils.go:165] 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
I0414 06:10:48.443075       1 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0414 06:10:48.443085       1 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0414 06:10:48.443126       1 azure_disk_utils.go:188] read cloud config from file: /etc/kubernetes/azure.json successfully
I0414 06:10:48.443332       1 azure_auth.go:245] Using AzurePublicCloud environment
I0414 06:10:48.443366       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0414 06:10:48.443409       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 1577 lines ...
Go Version: go1.18
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0414 05:50:11.602058    5024 azuredisk.go:165] driver userAgent: disk.csi.azure.com/v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f gc/go1.18 (amd64-windows) e2e-test
W0414 05:50:11.604474    5024 azure_disk_utils.go:226] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified.
I0414 05:50:11.605321    5024 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0414 05:50:11.605321    5024 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0414 05:50:11.605321    5024 azure_disk_utils.go:188] read cloud config from file: C:\k\azure.json successfully
I0414 05:50:11.607303    5024 azure_auth.go:245] Using AzurePublicCloud environment
I0414 05:50:11.609694    5024 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0414 05:50:11.612288    5024 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 16 lines ...
I0414 05:50:11.623012    5024 server.go:117] Listening for connections on address: &net.UnixAddr{Name:"C:\\\\var\\\\lib\\\\kubelet\\\\plugins\\\\disk.csi.azure.com\\\\csi.sock", Net:"unix"}
I0414 05:50:11.770576    5024 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0414 05:50:11.770576    5024 utils.go:78] GRPC request: {}
I0414 05:50:11.777410    5024 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f"}
I0414 05:50:12.149225    5024 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I0414 05:50:12.149298    5024 utils.go:78] GRPC request: {}
I0414 05:50:12.171447    5024 azure_instance_metadata.go:138] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I0414 05:50:12.171447    5024 nodeserver.go:372] NodeGetInfo: nodeName(capz-0my2-bps4g), VM Size(Standard_D4s_v3)
I0414 05:50:12.178006    5024 nodeserver.go:410] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I0414 05:50:12.178006    5024 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-0my2-bps4g"}
I0414 05:50:12.436353    5024 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0414 05:50:12.436353    5024 utils.go:78] GRPC request: {}
I0414 05:50:12.436353    5024 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f"}
... skipping 1345 lines ...
Go Version: go1.18
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0414 05:50:08.876161    5832 azuredisk.go:165] driver userAgent: disk.csi.azure.com/v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f gc/go1.18 (amd64-windows) e2e-test
W0414 05:50:08.878641    5832 azure_disk_utils.go:226] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified.
I0414 05:50:08.879233    5832 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0414 05:50:08.879266    5832 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0414 05:50:08.879354    5832 azure_disk_utils.go:188] read cloud config from file: C:\k\azure.json successfully
I0414 05:50:08.886554    5832 azure_auth.go:245] Using AzurePublicCloud environment
I0414 05:50:08.886554    5832 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0414 05:50:08.889135    5832 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 19 lines ...
I0414 05:50:08.947546    5832 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f"}
I0414 05:50:09.342904    5832 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0414 05:50:09.342904    5832 utils.go:78] GRPC request: {}
I0414 05:50:09.342904    5832 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.17.0-a3eaf97b446365c5e7247caad38acd6c6883f93f"}
I0414 05:50:09.622679    5832 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I0414 05:50:09.622748    5832 utils.go:78] GRPC request: {}
I0414 05:50:09.650221    5832 azure_instance_metadata.go:138] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I0414 05:50:09.655361    5832 nodeserver.go:372] NodeGetInfo: nodeName(capz-0my2-9g9mh), VM Size(Standard_D4s_v3)
I0414 05:50:09.655361    5832 nodeserver.go:410] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I0414 05:50:09.655361    5832 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-0my2-9g9mh"}
I0414 05:50:38.848662    5832 utils.go:77] GRPC call: /csi.v1.Identity/Probe
I0414 05:50:38.848662    5832 utils.go:78] GRPC request: {}
I0414 05:50:38.848662    5832 utils.go:84] GRPC response: {"ready":{"value":true}}
... skipping 548 lines ...
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-0my2ur",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 25
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-0my2ur",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 25
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-0my2ur",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 25
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-0my2ur",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 25
cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-0my2ur",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 375.83718264099997
cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-0my2ur",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 25
# 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-0my2ur",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"} 4.0403e-05
go_gc_duration_seconds{quantile="0.25"} 5.6405e-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 3076.622 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 (3076.65s)
FAIL
FAIL	sigs.k8s.io/azuredisk-csi-driver/test/e2e	3076.701s
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 93 lines ...