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-13 09:15
Elapsed1h25m
Revisiond7600c07bbfa811ac4d88920710966de02038df5
Refs 1280

Test Failures

AzureDisk CSI Driver End-to-End Tests Dynamic Provisioning [single-az] should create a volume on demand with mount options [kubernetes.io/azure-disk] [disk.csi.azure.com] [Windows] 14m2s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=AzureDisk\sCSI\sDriver\sEnd\-to\-End\sTests\sDynamic\sProvisioning\s\[single\-az\]\sshould\screate\sa\svolume\son\sdemand\swith\smount\soptions\s\[kubernetes\.io\/azure\-disk\]\s\[disk\.csi\.azure\.com\]\s\[Windows\]$'
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:101
Unexpected error:
    <*errors.errorString | 0xc00044a9b0>: {
        s: "pod \"azuredisk-volume-tester-6srjt\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.250.3 PodIPs:[{IP:192.168.250.3}] StartTime:2022-04-13 09:42:20 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:&ContainerStateWaiting{Reason:RunContainerError,Message:context deadline exceeded,} Running:nil Terminated:nil} LastTerminationState:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:,Message:,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085 Started:0xc000722cc8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
    }
    pod "azuredisk-volume-tester-6srjt" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.250.3 PodIPs:[{IP:192.168.250.3}] StartTime:2022-04-13 09:42:20 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:&ContainerStateWaiting{Reason:RunContainerError,Message:context deadline exceeded,} Running:nil Terminated:nil} LastTerminationState:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:,Message:,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085 Started:0xc000722cc8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
occurred
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:807
				
				Click to see stdout/stderrfrom junit_01.xml

Find azuredisk-volume-tester-6srjt mentions in log files | View test history on testgrid

Show 18 Passed Tests
Show 40 Skipped Tests

Error lines from build-log.txt

... skipping 581 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 129 lines ...
# Wait for the kubeconfig to become available.
timeout --foreground 300 bash -c "while ! kubectl get secrets | grep capz-vpcs68-kubeconfig; do sleep 1; done"
capz-vpcs68-kubeconfig                 cluster.x-k8s.io/secret               1      1s
# Get kubeconfig and store it locally.
kubectl get secrets capz-vpcs68-kubeconfig -o json | jq -r .data.value | base64 --decode > ./kubeconfig
timeout --foreground 600 bash -c "while ! kubectl --kubeconfig=./kubeconfig get nodes | grep control-plane; do sleep 1; done"
error: the server doesn't have a resource type "nodes"
capz-vpcs68-control-plane-2hd9f   NotReady   control-plane,master   10s   v1.23.5
run "kubectl --kubeconfig=./kubeconfig ..." to work with the new target cluster
make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Waiting for 1 control plane machine(s), 2 worker machine(s), and 2 windows machine(s) to become Ready
node/capz-vpcs-7jn54 condition met
node/capz-vpcs-lzddr condition met
... skipping 40 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11156  100 11156    0     0   201k      0 --:--:-- --:--:-- --:--:--  201k
Downloading https://get.helm.sh/helm-v3.8.1-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.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 || make container-all push-manifest
Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 not found: manifest unknown: manifest tagged by "v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635" 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.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2022-04-13T09:30:59Z -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 2203 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
Platform: linux/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
STEP: Building a namespace api object, basename azuredisk
W0413 09:42:14.663954   35706 azure_disk_utils.go:165] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
W0413 09:42:14.664723   35706 azuredisk.go:185] DisableAvailabilitySetNodes for controller is set as false while current VMType is vmss
I0413 09:42:14.665111   35706 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME
I0413 09:42:14.665127   35706 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0413 09:42:14.665131   35706 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0413 09:42:14.665135   35706 driver.go:81] Enabling controller service capability: CLONE_VOLUME
I0413 09:42:14.665140   35706 driver.go:81] Enabling controller service capability: EXPAND_VOLUME
... skipping 23 lines ...
Apr 13 09:42:19.980: INFO: PersistentVolumeClaim pvc-6q586 found and phase=Bound (4.174892025s)
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 13 09:42:20.160: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6srjt" in namespace "azuredisk-8081" to be "Succeeded or Failed"
Apr 13 09:42:20.217: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 57.113696ms
Apr 13 09:42:22.276: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.116233664s
Apr 13 09:42:24.333: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.17372425s
Apr 13 09:42:26.392: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.232339044s
Apr 13 09:42:28.452: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.291937774s
Apr 13 09:42:30.511: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.351148892s
... skipping 201 lines ...
Apr 13 09:49:27.098: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 7m6.938184479s
Apr 13 09:49:29.160: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 7m9.000670398s
Apr 13 09:49:31.222: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 7m11.062626155s
Apr 13 09:49:33.285: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 7m13.125444095s
Apr 13 09:49:35.347: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 7m15.187094999s
Apr 13 09:49:37.409: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Pending", Reason="", readiness=false. Elapsed: 7m17.249570645s
Apr 13 09:49:39.472: INFO: Pod "azuredisk-volume-tester-6srjt": Phase="Failed", Reason="", readiness=false. Elapsed: 7m19.31226926s
Apr 13 09:49:39.473: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-6srjt"
Apr 13 09:49:39.550: INFO: Pod azuredisk-volume-tester-6srjt has the following logs: 
STEP: Deleting pod azuredisk-volume-tester-6srjt in namespace azuredisk-8081
Apr 13 09:49:39.621: INFO: deleting PVC "azuredisk-8081"/"pvc-6q586"
Apr 13 09:49:39.621: INFO: Deleting PersistentVolumeClaim "pvc-6q586"
STEP: waiting for claim's PV "pvc-f034b0ba-b629-4e11-a923-9b0ce55ab4c5" to be deleted
... skipping 87 lines ...
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:42:18 +0000 UTC - event for pvc-6q586: {disk.csi.azure.com_capz-vpcs68-md-0-gm2tw_3d15a5e1-f199-43d6-871e-cdb5155e90ee } ProvisioningSucceeded: Successfully provisioned volume pvc-f034b0ba-b629-4e11-a923-9b0ce55ab4c5
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:42:20 +0000 UTC - event for azuredisk-volume-tester-6srjt: {default-scheduler } Scheduled: Successfully assigned azuredisk-8081/azuredisk-volume-tester-6srjt to capz-vpcs-lzddr
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:42:26 +0000 UTC - event for azuredisk-volume-tester-6srjt: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-f034b0ba-b629-4e11-a923-9b0ce55ab4c5" 
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:43:00 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:47:37 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m37.0553994s
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:47:37 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Created: Created container volume-tester
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:49:37 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Failed: Error: context deadline exceeded
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:49:37 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:49:41 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Started: Started container volume-tester
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:49:42 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} Killing: Stopping container volume-tester
Apr 13 09:56:14.580: INFO: At 2022-04-13 09:51:44 +0000 UTC - event for azuredisk-volume-tester-6srjt: {kubelet capz-vpcs-lzddr} FailedKillPod: error killing pod: failed to "KillPodSandbox" for "65a76086-6596-462a-aab4-88911c45b7d7" with KillPodSandboxError: "rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Apr 13 09:56:14.637: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 13 09:56:14.637: INFO: 
Apr 13 09:56:14.752: INFO: 
Logging node info for node capz-vpcs-7jn54
Apr 13 09:56:14.811: INFO: Node Info: &Node{ObjectMeta:{capz-vpcs-7jn54    955fc7a7-1445-4182-ba70-53a37f6032d8 4352 0 2022-04-13 09:28:34 +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:westus2 failure-domain.beta.kubernetes.io/zone:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-vpcs-7jn54 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:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-vpcs68 cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-vpcs68-md-win-7c58bb94db-bh4sq cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-vpcs68-md-win-7c58bb94db csi.volume.kubernetes.io/nodeid:{"disk.csi.azure.com":"capz-vpcs-7jn54"} 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.161.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:6c:a9:15 volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{kube-controller-manager Update v1 2022-04-13 09:28:35 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {Go-http-client Update v1 2022-04-13 09:28: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":{}}} } {manager Update v1 2022-04-13 09:28:50 +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-13 09:30: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-13 09:42:14 +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-vpcs68/providers/Microsoft.Compute/virtualMachines/capz-vpcs-7jn54,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-13 09:52:57 +0000 UTC,LastTransitionTime:2022-04-13 09:28:34 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-13 09:52:57 +0000 UTC,LastTransitionTime:2022-04-13 09:28:34 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-13 09:52:57 +0000 UTC,LastTransitionTime:2022-04-13 09:28:34 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-13 09:52:57 +0000 UTC,LastTransitionTime:2022-04-13 09:29:26 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-vpcs-7jn54,},NodeAddress{Type:InternalIP,Address:10.1.0.5,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-vpcs-7jn54,SystemUUID:2DBF05AE-DDB1-4665-B208-0629C1DBBB41,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:61a2e32fbb4b6722027417b9fe2ca6be53958707c8544393ba4f6fddb5239705 capzci.azurecr.io/azuredisk-csi:v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635],SizeBytes:141765990,},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 13 09:56:14.812: INFO: 
... skipping 114 lines ...
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:40
  [single-az]
  /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:43
    should create a volume on demand with mount options [kubernetes.io/azure-disk] [disk.csi.azure.com] [Windows] [It]
    /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:101

    Unexpected error:
        <*errors.errorString | 0xc00044a9b0>: {
            s: "pod \"azuredisk-volume-tester-6srjt\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.250.3 PodIPs:[{IP:192.168.250.3}] StartTime:2022-04-13 09:42:20 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:&ContainerStateWaiting{Reason:RunContainerError,Message:context deadline exceeded,} Running:nil Terminated:nil} LastTerminationState:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:,Message:,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085 Started:0xc000722cc8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
        }
        pod "azuredisk-volume-tester-6srjt" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [volume-tester]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-13 09:42:20 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.250.3 PodIPs:[{IP:192.168.250.3}] StartTime:2022-04-13 09:42:20 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:&ContainerStateWaiting{Reason:RunContainerError,Message:context deadline exceeded,} Running:nil Terminated:nil} LastTerminationState:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:,Message:,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://ae5cd4a181554cba0b9b58910032dba01f90a9f35c3dbe13c8ca468428cb5085 Started:0xc000722cc8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
    occurred

    /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:807
------------------------------
Dynamic Provisioning [single-az] 
  should create a pod with volume mount subpath [disk.csi.azure.com] [Windows]
... skipping 18 lines ...
Apr 13 09:56:20.615: INFO: PersistentVolumeClaim pvc-8j9rh found but phase is Pending instead of Bound.
Apr 13 09:56:22.673: INFO: PersistentVolumeClaim pvc-8j9rh found and phase=Bound (4.174422028s)
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 13 09:56:22.847: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-ltx5b" in namespace "azuredisk-2540" to be "Succeeded or Failed"
Apr 13 09:56:22.904: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 57.235627ms
Apr 13 09:56:24.962: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 2.115511688s
Apr 13 09:56:27.021: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 4.173981737s
Apr 13 09:56:29.079: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 6.231793949s
Apr 13 09:56:31.137: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 8.29063438s
Apr 13 09:56:33.195: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 10.348391043s
... skipping 15 lines ...
Apr 13 09:57:06.138: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Pending", Reason="", readiness=false. Elapsed: 43.291591976s
Apr 13 09:57:08.198: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Running", Reason="", readiness=true. Elapsed: 45.350881687s
Apr 13 09:57:10.259: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Running", Reason="", readiness=true. Elapsed: 47.411987716s
Apr 13 09:57:12.319: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Running", Reason="", readiness=true. Elapsed: 49.471935657s
Apr 13 09:57:14.379: INFO: Pod "azuredisk-volume-tester-ltx5b": Phase="Succeeded", Reason="", readiness=false. Elapsed: 51.532034877s
STEP: Saw pod success
Apr 13 09:57:14.379: INFO: Pod "azuredisk-volume-tester-ltx5b" satisfied condition "Succeeded or Failed"
Apr 13 09:57:14.379: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-ltx5b"
Apr 13 09:57:14.444: INFO: Pod azuredisk-volume-tester-ltx5b has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-ltx5b in namespace azuredisk-2540
Apr 13 09:57:14.508: INFO: deleting PVC "azuredisk-2540"/"pvc-8j9rh"
Apr 13 09:57:14.508: INFO: Deleting PersistentVolumeClaim "pvc-8j9rh"
... skipping 52 lines ...
Apr 13 09:58:30.774: INFO: PersistentVolumeClaim pvc-6vqd8 found and phase=Bound (4.174203146s)
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 13 09:58:30.950: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-wtc6g" in namespace "azuredisk-4728" to be "Succeeded or Failed"
Apr 13 09:58:31.007: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 56.703451ms
Apr 13 09:58:33.065: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.115412079s
Apr 13 09:58:35.123: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.172967087s
Apr 13 09:58:37.181: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.231098845s
Apr 13 09:58:39.239: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.288925583s
Apr 13 09:58:41.297: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.347122495s
... skipping 15 lines ...
Apr 13 09:59:14.240: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Pending", Reason="", readiness=false. Elapsed: 43.290466551s
Apr 13 09:59:16.301: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Running", Reason="", readiness=true. Elapsed: 45.351044824s
Apr 13 09:59:18.363: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Running", Reason="", readiness=true. Elapsed: 47.412891556s
Apr 13 09:59:20.422: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Running", Reason="", readiness=true. Elapsed: 49.472224964s
Apr 13 09:59:22.483: INFO: Pod "azuredisk-volume-tester-wtc6g": Phase="Succeeded", Reason="", readiness=false. Elapsed: 51.532816492s
STEP: Saw pod success
Apr 13 09:59:22.483: INFO: Pod "azuredisk-volume-tester-wtc6g" satisfied condition "Succeeded or Failed"
Apr 13 09:59:22.483: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-wtc6g"
Apr 13 09:59:22.556: INFO: Pod azuredisk-volume-tester-wtc6g has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-wtc6g in namespace azuredisk-4728
Apr 13 09:59:22.623: INFO: deleting PVC "azuredisk-4728"/"pvc-6vqd8"
Apr 13 09:59:22.623: INFO: Deleting PersistentVolumeClaim "pvc-6vqd8"
... skipping 102 lines ...
Apr 13 10:00:10.333: INFO: PersistentVolumeClaim pvc-rg5q6 found and phase=Bound (4.172726105s)
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 13 10:00:10.505: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-76877" in namespace "azuredisk-5356" to be "Error status code"
Apr 13 10:00:10.562: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 57.183609ms
Apr 13 10:00:12.619: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 2.114564979s
Apr 13 10:00:14.677: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 4.172434009s
Apr 13 10:00:16.769: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 6.263920851s
Apr 13 10:00:18.827: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 8.321838153s
Apr 13 10:00:20.885: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 10.379666132s
... skipping 25 lines ...
Apr 13 10:01:14.406: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 1m3.900872682s
Apr 13 10:01:16.465: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 1m5.960001844s
Apr 13 10:01:18.526: INFO: Pod "azuredisk-volume-tester-76877": Phase="Pending", Reason="", readiness=false. Elapsed: 1m8.0211774s
Apr 13 10:01:20.586: INFO: Pod "azuredisk-volume-tester-76877": Phase="Running", Reason="", readiness=true. Elapsed: 1m10.080667262s
Apr 13 10:01:22.646: INFO: Pod "azuredisk-volume-tester-76877": Phase="Running", Reason="", readiness=true. Elapsed: 1m12.141140712s
Apr 13 10:01:24.706: INFO: Pod "azuredisk-volume-tester-76877": Phase="Running", Reason="", readiness=true. Elapsed: 1m14.201417932s
Apr 13 10:01:26.766: INFO: Pod "azuredisk-volume-tester-76877": Phase="Failed", Reason="", readiness=false. Elapsed: 1m16.261562057s
STEP: Saw pod failure
Apr 13 10:01:26.767: INFO: Pod "azuredisk-volume-tester-76877" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 13 10:01:26.847: INFO: deleting Pod "azuredisk-5356"/"azuredisk-volume-tester-76877"
Apr 13 10:01:26.908: INFO: Pod azuredisk-volume-tester-76877 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 456 lines ...
Apr 13 10:09:38.510: INFO: PersistentVolumeClaim pvc-lpqtz found and phase=Bound (4.172811317s)
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 13 10:09:38.692: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-664ck" in namespace "azuredisk-59" to be "Succeeded or Failed"
Apr 13 10:09:38.750: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 58.0651ms
Apr 13 10:09:40.810: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 2.118673228s
Apr 13 10:09:42.870: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 4.178292725s
Apr 13 10:09:44.930: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 6.23809429s
Apr 13 10:09:46.990: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 8.298393455s
Apr 13 10:09:49.049: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 10.356972011s
... skipping 25 lines ...
Apr 13 10:10:42.614: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Pending", Reason="", readiness=false. Elapsed: 1m3.922173051s
Apr 13 10:10:44.673: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Running", Reason="", readiness=true. Elapsed: 1m5.98094204s
Apr 13 10:10:46.732: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Running", Reason="", readiness=true. Elapsed: 1m8.040597966s
Apr 13 10:10:48.792: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Running", Reason="", readiness=true. Elapsed: 1m10.100437009s
Apr 13 10:10:50.852: INFO: Pod "azuredisk-volume-tester-664ck": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m12.160022237s
STEP: Saw pod success
Apr 13 10:10:50.852: INFO: Pod "azuredisk-volume-tester-664ck" satisfied condition "Succeeded or Failed"
Apr 13 10:10:50.852: INFO: deleting Pod "azuredisk-59"/"azuredisk-volume-tester-664ck"
Apr 13 10:10:50.926: INFO: Pod azuredisk-volume-tester-664ck has the following logs: hello world
hello world
hello world

STEP: Deleting pod azuredisk-volume-tester-664ck in namespace azuredisk-59
... skipping 187 lines ...
Apr 13 10:13:07.810: INFO: PersistentVolumeClaim pvc-5vbxw found but phase is Pending instead of Bound.
Apr 13 10:13:09.868: INFO: PersistentVolumeClaim pvc-5vbxw found and phase=Bound (4.173892606s)
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 13 10:13:10.044: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p66fn" in namespace "azuredisk-8582" to be "Succeeded or Failed"
Apr 13 10:13:10.107: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 62.672433ms
Apr 13 10:13:12.166: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.122090451s
Apr 13 10:13:14.227: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.182595239s
Apr 13 10:13:16.287: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.242745865s
Apr 13 10:13:18.347: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.303215062s
Apr 13 10:13:20.408: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.363936833s
... skipping 19 lines ...
Apr 13 10:14:01.609: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Pending", Reason="", readiness=false. Elapsed: 51.565302881s
Apr 13 10:14:03.669: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Running", Reason="", readiness=true. Elapsed: 53.62537778s
Apr 13 10:14:05.729: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Running", Reason="", readiness=true. Elapsed: 55.685053065s
Apr 13 10:14:07.788: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Running", Reason="", readiness=true. Elapsed: 57.744059494s
Apr 13 10:14:09.848: INFO: Pod "azuredisk-volume-tester-p66fn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 59.803683963s
STEP: Saw pod success
Apr 13 10:14:09.848: INFO: Pod "azuredisk-volume-tester-p66fn" satisfied condition "Succeeded or Failed"
Apr 13 10:14:09.848: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-p66fn"
Apr 13 10:14:09.926: INFO: Pod azuredisk-volume-tester-p66fn has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-p66fn in namespace azuredisk-8582
Apr 13 10:14:09.995: INFO: deleting PVC "azuredisk-8582"/"pvc-5vbxw"
Apr 13 10:14:09.995: INFO: Deleting PersistentVolumeClaim "pvc-5vbxw"
... skipping 475 lines ...
Apr 13 10:25:42.067: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-gh5lx] to have phase Bound
Apr 13 10:25:42.133: INFO: PersistentVolumeClaim pvc-gh5lx found and phase=Bound (65.529448ms)
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 13 10:25:42.310: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gq2q5" in namespace "azuredisk-783" to be "Error status code"
Apr 13 10:25:42.369: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 58.819297ms
Apr 13 10:25:44.426: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.115282879s
Apr 13 10:25:46.484: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.173239861s
Apr 13 10:25:48.548: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.237518518s
Apr 13 10:25:50.609: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.298304697s
Apr 13 10:25:52.672: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.362082915s
... skipping 13 lines ...
Apr 13 10:26:21.492: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 39.181566674s
Apr 13 10:26:23.551: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 41.24113988s
Apr 13 10:26:25.611: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Pending", Reason="", readiness=false. Elapsed: 43.300419001s
Apr 13 10:26:27.670: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Running", Reason="", readiness=true. Elapsed: 45.35933516s
Apr 13 10:26:29.729: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Running", Reason="", readiness=true. Elapsed: 47.418981442s
Apr 13 10:26:31.789: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Running", Reason="", readiness=true. Elapsed: 49.47884275s
Apr 13 10:26:33.849: INFO: Pod "azuredisk-volume-tester-gq2q5": Phase="Failed", Reason="", readiness=false. Elapsed: 51.538382472s
STEP: Saw pod failure
Apr 13 10:26:33.849: INFO: Pod "azuredisk-volume-tester-gq2q5" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 13 10:26:33.917: INFO: deleting Pod "azuredisk-783"/"azuredisk-volume-tester-gq2q5"
Apr 13 10:26:33.978: INFO: Pod azuredisk-volume-tester-gq2q5 has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied.
At line:1 char:22
+ ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ...
+                         ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
... skipping 104 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 13 10:27:34.431: 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 13 10:27:38.988: INFO: PersistentVolumeClaim pvc-78247 found and phase=Bound (56.655311ms)
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 13 10:27:51.117: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-lpwxb" in namespace "azuredisk-8675" to be "Succeeded or Failed"
Apr 13 10:27:51.174: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 57.032825ms
Apr 13 10:27:53.232: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.11495747s
Apr 13 10:27:55.290: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.173093161s
Apr 13 10:27:57.348: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.231493304s
Apr 13 10:27:59.406: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.289004135s
Apr 13 10:28:01.464: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.346842379s
... skipping 24 lines ...
Apr 13 10:28:52.911: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Pending", Reason="", readiness=false. Elapsed: 1m1.794215952s
Apr 13 10:28:54.972: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Running", Reason="", readiness=true. Elapsed: 1m3.854877472s
Apr 13 10:28:57.031: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Running", Reason="", readiness=true. Elapsed: 1m5.91407666s
Apr 13 10:28:59.090: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Running", Reason="", readiness=true. Elapsed: 1m7.972956486s
Apr 13 10:29:01.148: INFO: Pod "azuredisk-volume-tester-lpwxb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m10.03164769s
STEP: Saw pod success
Apr 13 10:29:01.148: INFO: Pod "azuredisk-volume-tester-lpwxb" satisfied condition "Succeeded or Failed"
Apr 13 10:29:01.148: INFO: deleting Pod "azuredisk-8675"/"azuredisk-volume-tester-lpwxb"
Apr 13 10:29:01.222: INFO: Pod azuredisk-volume-tester-lpwxb has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-lpwxb in namespace azuredisk-8675
Apr 13 10:29:01.409: INFO: deleting PVC "azuredisk-8675"/"pvc-78247"
Apr 13 10:29:01.409: INFO: Deleting PersistentVolumeClaim "pvc-78247"
... skipping 118 lines ...
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0413 09:41:08.806833       1 azuredisk.go:165] driver userAgent: disk.csi.azure.com/v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 gc/go1.18 (amd64-linux) e2e-test
I0413 09:41:08.807184       1 azure_disk_utils.go:158] reading cloud config from secret kube-system/azure-cloud-provider
I0413 09:41:08.816337       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
W0413 09:41:08.816532       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
I0413 09:41:08.816549       1 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0413 09:41:08.816558       1 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0413 09:41:08.816589       1 azure_disk_utils.go:188] read cloud config from file: /etc/kubernetes/azure.json successfully
I0413 09:41:08.817106       1 azure_auth.go:245] Using AzurePublicCloud environment
I0413 09:41:08.817145       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0413 09:41:08.817207       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 244 lines ...
I0413 09:56:17.636674       1 utils.go:78] GRPC request: {}
I0413 09:56:17.636726       1 utils.go:84] GRPC response: {"ready":{"value":true}}
I0413 09:56:18.481591       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I0413 09:56:18.481617       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-0525f57e-5e8a-4efb-b6e3-16cfdf1c9f18","parameters":{"csi.storage.k8s.io/pv/name":"pvc-0525f57e-5e8a-4efb-b6e3-16cfdf1c9f18","csi.storage.k8s.io/pvc/name":"pvc-8j9rh","csi.storage.k8s.io/pvc/namespace":"azuredisk-2540","enableAsyncAttach":"false","networkAccessPolicy":"DenyAll","skuName":"Standard_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]}
I0413 09:56:18.482100       1 azure_disk_utils.go:158] reading cloud config from secret kube-system/azure-cloud-provider
I0413 09:56:18.492910       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 10 milliseconds
W0413 09:56:18.493063       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
I0413 09:56:18.493077       1 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0413 09:56:18.493087       1 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0413 09:56:18.493122       1 azure_disk_utils.go:188] read cloud config from file: /etc/kubernetes/azure.json successfully
I0413 09:56:18.493300       1 azure_auth.go:245] Using AzurePublicCloud environment
I0413 09:56:18.493331       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0413 09:56:18.493364       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 71 lines ...
I0413 09:58:22.793845       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=5.23075427 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-0525f57e-5e8a-4efb-b6e3-16cfdf1c9f18="" result_code="succeeded"
I0413 09:58:22.793862       1 utils.go:84] GRPC response: {}
I0413 09:58:26.586074       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I0413 09:58:26.586103       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-6fd22120-a8cd-47e3-a500-c1312e1e3d1d","parameters":{"csi.storage.k8s.io/pv/name":"pvc-6fd22120-a8cd-47e3-a500-c1312e1e3d1d","csi.storage.k8s.io/pvc/name":"pvc-6vqd8","csi.storage.k8s.io/pvc/namespace":"azuredisk-4728","enableAsyncAttach":"false","enableBursting":"true","perfProfile":"Basic","skuName":"Premium_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]}
I0413 09:58:26.586578       1 azure_disk_utils.go:158] reading cloud config from secret kube-system/azure-cloud-provider
I0413 09:58:26.595437       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 8 milliseconds
W0413 09:58:26.595554       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
I0413 09:58:26.595573       1 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0413 09:58:26.595582       1 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0413 09:58:26.595635       1 azure_disk_utils.go:188] read cloud config from file: /etc/kubernetes/azure.json successfully
I0413 09:58:26.595842       1 azure_auth.go:245] Using AzurePublicCloud environment
I0413 09:58:26.595880       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0413 09:58:26.595931       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 1288 lines ...
I0413 10:21:18.346575       1 azure_controller_common.go:341] Trying to detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495 from node capz-vpcs-lzddr, diskMap: map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-vpcs68/providers/microsoft.compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495:pvc-a66381d9-5688-4695-aabd-44c7b2ac2495]
E0413 10:21:18.346597       1 azure_controller_standard.go:163] detach azure disk on node(capz-vpcs-lzddr): disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-vpcs68/providers/microsoft.compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495:pvc-a66381d9-5688-4695-aabd-44c7b2ac2495]) not found
I0413 10:21:18.346609       1 azure_controller_standard.go:184] azureDisk - update(capz-vpcs68): vm(capz-vpcs-lzddr) - detach disk list(capz-vpcs-lzddr)%!(EXTRA map[string]string=map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-vpcs68/providers/microsoft.compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495:pvc-a66381d9-5688-4695-aabd-44c7b2ac2495])
I0413 10:21:23.534514       1 utils.go:77] GRPC call: /csi.v1.Controller/DeleteVolume
I0413 10:21:23.534542       1 utils.go:78] GRPC request: {"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495"}
I0413 10:21:23.534624       1 controllerserver.go:294] deleting azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495)
I0413 10:21:23.534641       1 controllerserver.go:296] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495) returned with failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495) since it's in attaching or detaching state
I0413 10:21:23.534708       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=2.8501e-05 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495="" result_code="failed"
E0413 10:21:23.534719       1 utils.go:82] GRPC error: failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495) since it's in attaching or detaching state
I0413 10:21:23.757502       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=5.410853919 request="vm_update" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="detach_disk" error_code=""
I0413 10:21:23.757532       1 azure_controller_standard.go:201] azureDisk - update(capz-vpcs68): vm(capz-vpcs-lzddr) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-vpcs68/providers/microsoft.compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495:pvc-a66381d9-5688-4695-aabd-44c7b2ac2495]) returned with <nil>
I0413 10:21:23.757556       1 azure_controller_common.go:365] azureDisk - detach disk(pvc-a66381d9-5688-4695-aabd-44c7b2ac2495, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495) succeeded
I0413 10:21:23.757568       1 controllerserver.go:448] detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495 from node capz-vpcs-lzddr successfully
I0413 10:21:23.757590       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=5.543319256 request="azuredisk_csi_driver_controller_unpublish_volume" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-a66381d9-5688-4695-aabd-44c7b2ac2495=capz-vpcs-lzddr result_code="succeeded"
I0413 10:21:23.757604       1 utils.go:84] GRPC response: {}
... skipping 262 lines ...
I0413 10:28:01.825974       1 azure_controller_common.go:365] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded
I0413 10:28:01.825991       1 controllerserver.go:393] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-vpcs-lzddr again
I0413 10:28:01.826003       1 azure_vmss_cache.go:332] Node capz-vpcs-lzddr has joined the cluster since the last VM cache refresh, refreshing the cache
I0413 10:28:01.862350       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.036312921 request="vm_list" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I0413 10:28:01.862376       1 azure_backoff.go:101] VirtualMachinesClient.List(capz-vpcs68) success
I0413 10:28:01.862408       1 azure_controller_common.go:174] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-vpcs-7jn54, could not be attached to node(capz-vpcs-lzddr)
E0413 10:28:01.862424       1 controllerserver.go:397] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-vpcs-lzddr failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/virtualMachines/capz-vpcs-7jn54), could not be attached to node(capz-vpcs-lzddr)
I0413 10:28:01.862457       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=10.634884824 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes=capz-vpcs-lzddr result_code="failed"
E0413 10:28:01.862476       1 utils.go:82] GRPC error: Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-vpcs-lzddr failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/virtualMachines/capz-vpcs-7jn54), could not be attached to node(capz-vpcs-lzddr)
I0413 10:28:01.871238       1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0413 10:28:01.871262       1 utils.go:78] GRPC request: {"node_id":"capz-vpcs-lzddr","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-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"}
I0413 10:28:01.900402       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.028979735 request="disks_get" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I0413 10:28:01.900448       1 controllerserver.go:350] GetDiskLun returned: <nil>. Initiating attaching volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-vpcs-lzddr.
I0413 10:28:01.900462       1 azure_vmss_cache.go:332] Node capz-vpcs-lzddr has joined the cluster since the last VM cache refresh, refreshing the cache
I0413 10:28:01.950480       1 azure_metrics.go:112] "Observed Request Latency" latency_seconds=0.049982379 request="vm_list" resource_group="capz-vpcs68" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
... skipping 140 lines ...
Go Version: go1.18
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0413 09:42:12.728762    5032 azuredisk.go:165] driver userAgent: disk.csi.azure.com/v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 gc/go1.18 (amd64-windows) e2e-test
W0413 09:42:12.730491    5032 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.
I0413 09:42:12.731093    5032 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0413 09:42:12.731093    5032 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0413 09:42:12.731093    5032 azure_disk_utils.go:188] read cloud config from file: C:\k\azure.json successfully
I0413 09:42:12.737327    5032 azure_auth.go:245] Using AzurePublicCloud environment
I0413 09:42:12.737936    5032 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0413 09:42:12.739418    5032 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 19 lines ...
I0413 09:42:13.382097    5032 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635"}
I0413 09:42:13.417568    5032 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0413 09:42:13.417568    5032 utils.go:78] GRPC request: {}
I0413 09:42:13.417568    5032 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635"}
I0413 09:42:14.294400    5032 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I0413 09:42:14.294400    5032 utils.go:78] GRPC request: {}
I0413 09:42:14.315453    5032 azure_instance_metadata.go:138] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I0413 09:42:14.315453    5032 nodeserver.go:372] NodeGetInfo: nodeName(capz-vpcs-7jn54), VM Size(Standard_D4s_v3)
I0413 09:42:14.315453    5032 nodeserver.go:410] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I0413 09:42:14.315453    5032 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-vpcs-7jn54"}
I0413 09:42:47.580230    5032 utils.go:77] GRPC call: /csi.v1.Identity/Probe
I0413 09:42:47.580230    5032 utils.go:78] GRPC request: {}
I0413 09:42:47.580230    5032 utils.go:84] GRPC response: {"ready":{"value":true}}
... skipping 301 lines ...
Go Version: go1.18
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I0413 09:42:12.869570    4936 azuredisk.go:165] driver userAgent: disk.csi.azure.com/v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635 gc/go1.18 (amd64-windows) e2e-test
W0413 09:42:12.872011    4936 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.
I0413 09:42:12.872011    4936 azure_disk_utils.go:170] could not read cloud config from secret kube-system/azure-cloud-provider
I0413 09:42:12.872011    4936 azure_disk_utils.go:180] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0413 09:42:12.872011    4936 azure_disk_utils.go:188] read cloud config from file: C:\k\azure.json successfully
I0413 09:42:12.873842    4936 azure_auth.go:245] Using AzurePublicCloud environment
I0413 09:42:12.874425    4936 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0413 09:42:12.875589    4936 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 19 lines ...
I0413 09:42:13.276711    4936 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635"}
I0413 09:42:13.730222    4936 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I0413 09:42:13.730222    4936 utils.go:78] GRPC request: {}
I0413 09:42:13.730222    4936 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.16.0-eb7e0710ddbc5984b82c0c8453e3a2427fa2a635"}
I0413 09:42:13.872998    4936 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I0413 09:42:13.872998    4936 utils.go:78] GRPC request: {}
I0413 09:42:13.890346    4936 azure_instance_metadata.go:138] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I0413 09:42:13.890346    4936 nodeserver.go:372] NodeGetInfo: nodeName(capz-vpcs-lzddr), VM Size(Standard_D4s_v3)
I0413 09:42:13.890346    4936 nodeserver.go:410] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I0413 09:42:13.890346    4936 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-vpcs-lzddr"}
I0413 09:42:26.281648    4936 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0413 09:42:26.281648    4936 utils.go:78] GRPC request: {}
I0413 09:42:26.281648    4936 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
... skipping 1097 lines ...
I0413 10:24:30.213120    4936 nodeserver.go:303] NodeUnpublishVolume: unmounting volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-9e985f4e-630e-4b4e-977c-346758c01638 on c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc-9e985f4e-630e-4b4e-977c-346758c01638\mount
I0413 10:24:32.753683    4936 nodeserver.go:309] NodeUnpublishVolume: unmount volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-9e985f4e-630e-4b4e-977c-346758c01638 on c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc-9e985f4e-630e-4b4e-977c-346758c01638\mount successfully
I0413 10:24:32.753683    4936 utils.go:84] GRPC response: {}
I0413 10:24:33.282515    4936 utils.go:77] GRPC call: /csi.v1.Node/NodeUnpublishVolume
I0413 10:24:33.282515    4936 utils.go:78] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\021fada6-d798-4125-9cb5-064774c1a729\\volumes\\kubernetes.io~csi\\pvc-9e985f4e-630e-4b4e-977c-346758c01638\\mount","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-9e985f4e-630e-4b4e-977c-346758c01638"}
I0413 10:24:33.282515    4936 nodeserver.go:303] NodeUnpublishVolume: unmounting volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-9e985f4e-630e-4b4e-977c-346758c01638 on c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc-9e985f4e-630e-4b4e-977c-346758c01638\mount
W0413 10:24:33.864170    4936 safe_mounter_windows.go:110] GetVolumeIDFromTargetPath(c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc-9e985f4e-630e-4b4e-977c-346758c01638\mount) failed with error: rpc error: code = Unknown desc = error getting the volume for the mount c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc-9e985f4e-630e-4b4e-977c-346758c01638\mount, internal error error getting volume from mount. cmd: (Get-Item -Path Get-Item : Cannot find path 'C:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc
-9e985f4e-630e-4b4e-977c-346758c01638\mount' because it does not exist.
At line:1 char:2
+ (Get-Item -Path c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-06477 ...
+  ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (C:\var\lib\kube...758c01638\mount:String) [Get-Item], ItemNotFoundExcep 
   tion
... skipping 37 lines ...
+ ... d : PathNotFound,Microsoft.PowerShell.Commands.GetItemCommand).Target
+                                                                  ~
Unexpected token ')' in expression or statement.
    + CategoryInfo          : ParserError: (:) [], ParentContainsErrorRecordException
    + FullyQualifiedErrorId : MissingEndParenthesisInExpression
 
, error: exit status 1, response: <nil>
I0413 10:24:33.867209    4936 nodeserver.go:309] NodeUnpublishVolume: unmount volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vpcs68/providers/Microsoft.Compute/disks/pvc-9e985f4e-630e-4b4e-977c-346758c01638 on c:\var\lib\kubelet\pods\021fada6-d798-4125-9cb5-064774c1a729\volumes\kubernetes.io~csi\pvc-9e985f4e-630e-4b4e-977c-346758c01638\mount successfully
I0413 10:24:33.867209    4936 utils.go:84] GRPC response: {}
I0413 10:24:33.931947    4936 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0413 10:24:33.931947    4936 utils.go:78] GRPC request: {}
I0413 10:24:33.931947    4936 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
I0413 10:24:33.933872    4936 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume
... skipping 494 lines ...
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 29
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 29
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 29
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 29
cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 436.15587786000003
cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 29
# 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_delete_volume",resource_group="capz-vpcs68",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1
cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-vpcs68",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"} 3.76e-05
... skipping 198 lines ...

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


Summarizing 1 Failure:

[Fail] Dynamic Provisioning [single-az] [It] should create a volume on demand with mount options [kubernetes.io/azure-disk] [disk.csi.azure.com] [Windows] 
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:807

Ran 19 of 59 Specs in 3659.311 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 (3659.33s)
FAIL
FAIL	sigs.k8s.io/azuredisk-csi-driver/test/e2e	3659.392s
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 94 lines ...