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 / 19 succeeded
Started2022-04-18 12:37
Elapsed45m52s
Revision406a0d30aff10d48525d3e58710a2b1ac4047aa0
Refs 988

Test Failures

AzureFile CSI Driver End-to-End Tests Pre-Provisioned should use a pre-provisioned volume and mount it as readOnly in a pod [file.csi.azure.com] [Windows] 7m10s

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

Filter through log files | View test history on testgrid

Show 19 Passed Tests
Show 14 Skipped Tests

Error lines from build-log.txt

... skipping 671 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 1172 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'
            - '-timeout=120s'
            - '-feature-gates=RecoverVolumeExpansionFailure=true'
          env:
            - name: ADDRESS
              value: /csi/csi.sock
          imagePullPolicy: IfNotPresent
... skipping 148 lines ...
Git Commit: N/A
Go Version: go1.18.1
Platform: linux/amd64

Streaming logs below:
STEP: Building a namespace api object, basename azurefile
W0418 12:55:58.469726   37206 azure.go:78] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
I0418 12:55:58.470472   37206 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0418 12:55:58.470481   37206 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0418 12:55:58.470486   37206 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0418 12:55:58.470490   37206 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0418 12:55:58.470493   37206 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
I0418 12:55:58.470499   37206 driver.go:112] Enabling volume access mode: SINGLE_NODE_WRITER
... skipping 23 lines ...
Apr 18 12:56:30.953: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-fvd64] to have phase Bound
Apr 18 12:56:31.054: INFO: PersistentVolumeClaim pvc-fvd64 found and phase=Bound (101.74988ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with an error
Apr 18 12:56:31.361: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-v9rq4" in namespace "azurefile-8081" to be "Error status code"
Apr 18 12:56:31.463: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 102.021618ms
Apr 18 12:56:33.565: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204393448s
Apr 18 12:56:35.669: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.308105395s
Apr 18 12:56:37.771: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.410253327s
Apr 18 12:56:39.873: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.512474734s
Apr 18 12:56:41.982: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.621807929s
... skipping 173 lines ...
Apr 18 13:02:49.139: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m17.778630117s
Apr 18 13:02:51.249: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m19.888753799s
Apr 18 13:02:53.358: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m21.997602968s
Apr 18 13:02:55.468: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m24.107847622s
Apr 18 13:02:57.579: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m26.218639207s
Apr 18 13:02:59.688: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m28.327467218s
Apr 18 13:03:01.798: INFO: Pod "azurefile-volume-tester-v9rq4": Phase="Failed", Reason="", readiness=false. Elapsed: 6m30.43717442s
STEP: Saw pod failure
Apr 18 13:03:01.798: INFO: Pod "azurefile-volume-tester-v9rq4" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 13:03:01.917: INFO: deleting Pod "azurefile-8081"/"azurefile-volume-tester-v9rq4"
Apr 18 13:03:02.022: INFO: Pod azurefile-volume-tester-v9rq4 has the following logs: 
STEP: Deleting pod azurefile-volume-tester-v9rq4 in namespace azurefile-8081
Apr 18 13:03:02.141: INFO: deleting PVC "azurefile-8081"/"pvc-fvd64"
Apr 18 13:03:02.141: INFO: Deleting PersistentVolumeClaim "pvc-fvd64"
... skipping 7 lines ...
STEP: Collecting events from namespace "azurefile-8081".
STEP: Found 6 events.
Apr 18 13:03:02.659: INFO: At 2022-04-18 12:56:31 +0000 UTC - event for azurefile-volume-tester-v9rq4: {default-scheduler } Scheduled: Successfully assigned azurefile-8081/azurefile-volume-tester-v9rq4 to capz-vcrg-cnk6s
Apr 18 13:03:02.659: INFO: At 2022-04-18 12:56:42 +0000 UTC - event for azurefile-volume-tester-v9rq4: {kubelet capz-vcrg-cnk6s} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 18 13:03:02.659: INFO: At 2022-04-18 13:01:00 +0000 UTC - event for azurefile-volume-tester-v9rq4: {kubelet capz-vcrg-cnk6s} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m17.5126358s
Apr 18 13:03:02.659: INFO: At 2022-04-18 13:01:00 +0000 UTC - event for azurefile-volume-tester-v9rq4: {kubelet capz-vcrg-cnk6s} Created: Created container volume-tester
Apr 18 13:03:02.659: INFO: At 2022-04-18 13:03:00 +0000 UTC - event for azurefile-volume-tester-v9rq4: {kubelet capz-vcrg-cnk6s} Failed: Error: context deadline exceeded
Apr 18 13:03:02.659: INFO: At 2022-04-18 13:03:01 +0000 UTC - event for azurefile-volume-tester-v9rq4: {kubelet capz-vcrg-cnk6s} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 18 13:03:02.761: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 13:03:02.761: INFO: 
Apr 18 13:03:02.966: INFO: 
Logging node info for node capz-vcrg-cd9rs
Apr 18 13:03:03.071: INFO: Node Info: &Node{ObjectMeta:{capz-vcrg-cd9rs    4e0549ee-f144-4331-8d8c-8428eb8ffe5d 2669 0 2022-04-18 12:50:54 +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:uksouth failure-domain.beta.kubernetes.io/zone:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-vcrg-cd9rs kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:uksouth topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-vcrgvu cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-vcrgvu-md-win-57bc666585-k2hzt cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-vcrgvu-md-win-57bc666585 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-vcrg-cd9rs"} 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.213.193 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:d8:f0:ce volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 12:50:55 +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-18 12:51:04 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 12:51:12 +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-18 12:52:36 +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-18 12:55:55 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"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-vcrgvu/providers/Microsoft.Compute/virtualMachines/capz-vcrg-cd9rs,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-18 13:01:07 +0000 UTC,LastTransitionTime:2022-04-18 12:50:54 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 13:01:07 +0000 UTC,LastTransitionTime:2022-04-18 12:50:54 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 13:01:07 +0000 UTC,LastTransitionTime:2022-04-18 12:50:54 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 13:01:07 +0000 UTC,LastTransitionTime:2022-04-18 12:52:05 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-vcrg-cd9rs,},NodeAddress{Type:InternalIP,Address:10.1.0.4,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-vcrg-cd9rs,SystemUUID:30F91384-076E-4382-8A61-74BDF280049E,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/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},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,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 146 lines ...
Apr 18 13:03:12.318: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-8nqf7] to have phase Bound
Apr 18 13:03:12.420: INFO: PersistentVolumeClaim pvc-8nqf7 found and phase=Bound (101.765018ms)
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 18 13:03:12.730: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-kfpjx" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 13:03:12.834: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Pending", Reason="", readiness=false. Elapsed: 103.537642ms
Apr 18 13:03:14.937: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206523423s
Apr 18 13:03:17.042: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.311478044s
Apr 18 13:03:19.147: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.417099924s
Apr 18 13:03:21.253: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522828171s
Apr 18 13:03:23.358: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Running", Reason="", readiness=true. Elapsed: 10.628301803s
Apr 18 13:03:25.465: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Running", Reason="", readiness=true. Elapsed: 12.734857717s
Apr 18 13:03:27.570: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Running", Reason="", readiness=true. Elapsed: 14.839915328s
Apr 18 13:03:29.676: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Running", Reason="", readiness=true. Elapsed: 16.946177597s
Apr 18 13:03:31.781: INFO: Pod "azurefile-volume-tester-kfpjx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.05132381s
STEP: Saw pod success
Apr 18 13:03:31.781: INFO: Pod "azurefile-volume-tester-kfpjx" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 13:03:31.987: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-78fm6] to have phase Bound
Apr 18 13:03:32.088: INFO: PersistentVolumeClaim pvc-78fm6 found and phase=Bound (101.694293ms)
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 18 13:03:32.400: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-fl9sk" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 13:03:32.501: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Pending", Reason="", readiness=false. Elapsed: 101.289292ms
Apr 18 13:03:34.606: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206381177s
Apr 18 13:03:36.712: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.312739543s
Apr 18 13:03:38.818: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.418147708s
Apr 18 13:03:40.923: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.52339029s
Apr 18 13:03:43.029: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Running", Reason="", readiness=true. Elapsed: 10.629674845s
Apr 18 13:03:45.136: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Running", Reason="", readiness=true. Elapsed: 12.735929857s
Apr 18 13:03:47.243: INFO: Pod "azurefile-volume-tester-fl9sk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.84306079s
STEP: Saw pod success
Apr 18 13:03:47.243: INFO: Pod "azurefile-volume-tester-fl9sk" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 13:03:47.450: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lm468] to have phase Bound
Apr 18 13:03:47.553: INFO: PersistentVolumeClaim pvc-lm468 found and phase=Bound (102.186887ms)
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 18 13:03:47.860: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dr9dq" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 13:03:47.964: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Pending", Reason="", readiness=false. Elapsed: 104.116097ms
Apr 18 13:03:50.067: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206997586s
Apr 18 13:03:52.172: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.312312771s
Apr 18 13:03:54.277: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.417117674s
Apr 18 13:03:56.382: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.52219026s
Apr 18 13:03:58.488: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Running", Reason="", readiness=true. Elapsed: 10.628022303s
Apr 18 13:04:00.594: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Running", Reason="", readiness=true. Elapsed: 12.734111294s
Apr 18 13:04:02.699: INFO: Pod "azurefile-volume-tester-dr9dq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.839077169s
STEP: Saw pod success
Apr 18 13:04:02.699: INFO: Pod "azurefile-volume-tester-dr9dq" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 13:04:02.904: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-frh4w] to have phase Bound
Apr 18 13:04:03.006: INFO: PersistentVolumeClaim pvc-frh4w found and phase=Bound (101.404055ms)
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 18 13:04:03.311: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-fb4rg" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 13:04:03.413: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Pending", Reason="", readiness=false. Elapsed: 101.929283ms
Apr 18 13:04:05.530: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218601328s
Apr 18 13:04:07.636: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.324640401s
Apr 18 13:04:09.741: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.429144921s
Apr 18 13:04:11.846: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.534863945s
Apr 18 13:04:13.951: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Running", Reason="", readiness=true. Elapsed: 10.639729019s
Apr 18 13:04:16.057: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Running", Reason="", readiness=true. Elapsed: 12.745807549s
Apr 18 13:04:18.163: INFO: Pod "azurefile-volume-tester-fb4rg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.851634873s
STEP: Saw pod success
Apr 18 13:04:18.163: INFO: Pod "azurefile-volume-tester-fb4rg" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 13:04:18.370: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lf5rj] to have phase Bound
Apr 18 13:04:18.473: INFO: PersistentVolumeClaim pvc-lf5rj found and phase=Bound (102.802947ms)
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 18 13:04:18.781: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-b6kg4" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 13:04:18.882: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Pending", Reason="", readiness=false. Elapsed: 101.588978ms
Apr 18 13:04:20.988: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20711436s
Apr 18 13:04:23.093: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.312099945s
Apr 18 13:04:25.198: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.417872204s
Apr 18 13:04:27.304: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Running", Reason="", readiness=true. Elapsed: 8.523771607s
Apr 18 13:04:29.409: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Running", Reason="", readiness=true. Elapsed: 10.628706885s
Apr 18 13:04:31.516: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Running", Reason="", readiness=true. Elapsed: 12.734902297s
Apr 18 13:04:33.620: INFO: Pod "azurefile-volume-tester-b6kg4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.839826852s
STEP: Saw pod success
Apr 18 13:04:33.620: INFO: Pod "azurefile-volume-tester-b6kg4" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 13:04:33.825: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-zsfm6] to have phase Bound
Apr 18 13:04:33.928: INFO: PersistentVolumeClaim pvc-zsfm6 found and phase=Bound (102.52322ms)
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 18 13:04:34.238: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dx4v4" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 13:04:34.340: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Pending", Reason="", readiness=false. Elapsed: 101.200256ms
Apr 18 13:04:36.443: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204748439s
Apr 18 13:04:38.549: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.310196642s
Apr 18 13:04:40.655: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.416134949s
Apr 18 13:04:42.760: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.521537452s
Apr 18 13:04:44.865: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Running", Reason="", readiness=true. Elapsed: 10.626888442s
Apr 18 13:04:46.971: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Running", Reason="", readiness=true. Elapsed: 12.732182136s
Apr 18 13:04:49.077: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Running", Reason="", readiness=true. Elapsed: 14.838587369s
Apr 18 13:04:51.182: INFO: Pod "azurefile-volume-tester-dx4v4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.943909355s
STEP: Saw pod success
Apr 18 13:04:51.182: INFO: Pod "azurefile-volume-tester-dx4v4" satisfied condition "Succeeded or Failed"
Apr 18 13:04:51.182: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-dx4v4"
Apr 18 13:04:51.302: INFO: Pod azurefile-volume-tester-dx4v4 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-dx4v4 in namespace azurefile-2540
Apr 18 13:04:51.416: INFO: deleting PVC "azurefile-2540"/"pvc-zsfm6"
Apr 18 13:04:51.416: INFO: Deleting PersistentVolumeClaim "pvc-zsfm6"
... skipping 148 lines ...
Apr 18 13:05:04.042: INFO: PersistentVolumeClaim pvc-zndc6 found but phase is Pending instead of Bound.
Apr 18 13:05:06.145: INFO: PersistentVolumeClaim pvc-zndc6 found and phase=Bound (2.20454214s)
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 18 13:05:06.451: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-f8kjt" in namespace "azurefile-5466" to be "Succeeded or Failed"
Apr 18 13:05:06.553: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Pending", Reason="", readiness=false. Elapsed: 101.278217ms
Apr 18 13:05:08.655: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.203782091s
Apr 18 13:05:10.761: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309627038s
Apr 18 13:05:12.866: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.414392074s
Apr 18 13:05:14.972: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.520559904s
Apr 18 13:05:17.078: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Running", Reason="", readiness=true. Elapsed: 10.626255932s
Apr 18 13:05:19.183: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Running", Reason="", readiness=true. Elapsed: 12.731699741s
Apr 18 13:05:21.288: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Running", Reason="", readiness=true. Elapsed: 14.836986657s
Apr 18 13:05:23.393: INFO: Pod "azurefile-volume-tester-f8kjt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.941391213s
STEP: Saw pod success
Apr 18 13:05:23.393: INFO: Pod "azurefile-volume-tester-f8kjt" satisfied condition "Succeeded or Failed"
Apr 18 13:05:23.393: INFO: deleting Pod "azurefile-5466"/"azurefile-volume-tester-f8kjt"
Apr 18 13:05:23.503: INFO: Pod azurefile-volume-tester-f8kjt has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-f8kjt in namespace azurefile-5466
Apr 18 13:05:23.618: INFO: deleting PVC "azurefile-5466"/"pvc-zndc6"
Apr 18 13:05:23.618: INFO: Deleting PersistentVolumeClaim "pvc-zndc6"
... skipping 33 lines ...
Apr 18 13:05:27.527: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lfrqd] to have phase Bound
Apr 18 13:05:27.628: INFO: PersistentVolumeClaim pvc-lfrqd found and phase=Bound (101.416808ms)
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 18 13:05:27.934: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-h8b4q" in namespace "azurefile-2790" to be "Succeeded or Failed"
Apr 18 13:05:28.036: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Pending", Reason="", readiness=false. Elapsed: 101.699029ms
Apr 18 13:05:30.139: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205253662s
Apr 18 13:05:32.245: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.311110844s
Apr 18 13:05:34.351: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.417072763s
Apr 18 13:05:36.456: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522047737s
Apr 18 13:05:38.562: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Running", Reason="", readiness=true. Elapsed: 10.62800398s
Apr 18 13:05:40.668: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Running", Reason="", readiness=true. Elapsed: 12.734099009s
Apr 18 13:05:42.774: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Running", Reason="", readiness=true. Elapsed: 14.839758512s
Apr 18 13:05:44.880: INFO: Pod "azurefile-volume-tester-h8b4q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.945831823s
STEP: Saw pod success
Apr 18 13:05:44.880: INFO: Pod "azurefile-volume-tester-h8b4q" satisfied condition "Succeeded or Failed"
Apr 18 13:05:44.880: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-h8b4q"
Apr 18 13:05:44.990: INFO: Pod azurefile-volume-tester-h8b4q has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-h8b4q in namespace azurefile-2790
Apr 18 13:05:45.100: INFO: deleting PVC "azurefile-2790"/"pvc-lfrqd"
Apr 18 13:05:45.100: INFO: Deleting PersistentVolumeClaim "pvc-lfrqd"
... skipping 133 lines ...
Apr 18 13:07:51.621: INFO: PersistentVolumeClaim pvc-wt5wb found and phase=Bound (1m38.937270834s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 13:07:52.928: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-6ggbj" in namespace "azurefile-5194" to be "Succeeded or Failed"
Apr 18 13:07:53.031: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 102.625115ms
Apr 18 13:07:55.135: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206122875s
Apr 18 13:07:57.238: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309751402s
Apr 18 13:07:59.342: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.413040767s
Apr 18 13:08:01.444: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.515764084s
Apr 18 13:08:03.547: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.618788624s
... skipping 20 lines ...
Apr 18 13:08:47.718: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 54.78966194s
Apr 18 13:08:49.823: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Pending", Reason="", readiness=false. Elapsed: 56.89426503s
Apr 18 13:08:51.928: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Running", Reason="", readiness=true. Elapsed: 58.999352404s
Apr 18 13:08:54.034: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Running", Reason="", readiness=true. Elapsed: 1m1.105123997s
Apr 18 13:08:56.139: INFO: Pod "azurefile-volume-tester-6ggbj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m3.210453327s
STEP: Saw pod success
Apr 18 13:08:56.139: INFO: Pod "azurefile-volume-tester-6ggbj" satisfied condition "Succeeded or Failed"
Apr 18 13:08:56.139: INFO: deleting Pod "azurefile-5194"/"azurefile-volume-tester-6ggbj"
Apr 18 13:08:56.260: INFO: Pod azurefile-volume-tester-6ggbj has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-6ggbj in namespace azurefile-5194
Apr 18 13:08:56.374: INFO: deleting PVC "azurefile-5194"/"pvc-wt5wb"
Apr 18 13:08:56.374: INFO: Deleting PersistentVolumeClaim "pvc-wt5wb"
... skipping 34 lines ...
Apr 18 13:08:58.925: INFO: PersistentVolumeClaim pvc-dn7wx found but phase is Pending instead of Bound.
Apr 18 13:09:01.027: INFO: PersistentVolumeClaim pvc-dn7wx found and phase=Bound (2.203719044s)
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 18 13:09:01.335: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4fvhh" in namespace "azurefile-1353" to be "Succeeded or Failed"
Apr 18 13:09:01.437: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 101.501926ms
Apr 18 13:09:03.539: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.203614589s
Apr 18 13:09:05.645: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309588497s
Apr 18 13:09:07.750: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.414865879s
Apr 18 13:09:09.856: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.520672325s
Apr 18 13:09:11.962: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.626514233s
Apr 18 13:09:14.068: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Pending", Reason="", readiness=false. Elapsed: 12.732798459s
Apr 18 13:09:16.174: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Running", Reason="", readiness=true. Elapsed: 14.839153063s
Apr 18 13:09:18.281: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Running", Reason="", readiness=true. Elapsed: 16.945545203s
Apr 18 13:09:20.387: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Running", Reason="", readiness=true. Elapsed: 19.051535708s
Apr 18 13:09:22.493: INFO: Pod "azurefile-volume-tester-4fvhh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 21.157727156s
STEP: Saw pod success
Apr 18 13:09:22.493: INFO: Pod "azurefile-volume-tester-4fvhh" satisfied condition "Succeeded or Failed"
Apr 18 13:09:22.493: INFO: deleting Pod "azurefile-1353"/"azurefile-volume-tester-4fvhh"
Apr 18 13:09:22.604: INFO: Pod azurefile-volume-tester-4fvhh has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-4fvhh in namespace azurefile-1353
Apr 18 13:09:22.715: INFO: deleting PVC "azurefile-1353"/"pvc-dn7wx"
Apr 18 13:09:22.715: INFO: Deleting PersistentVolumeClaim "pvc-dn7wx"
... skipping 115 lines ...
Apr 18 13:10:25.551: INFO: PersistentVolumeClaim pvc-jqgzv found but phase is Pending instead of Bound.
Apr 18 13:10:27.655: INFO: PersistentVolumeClaim pvc-jqgzv found and phase=Bound (21.13257315s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with an error
Apr 18 13:10:27.963: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-ht2pz" in namespace "azurefile-156" to be "Error status code"
Apr 18 13:10:28.064: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Pending", Reason="", readiness=false. Elapsed: 101.629265ms
Apr 18 13:10:30.167: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.203962969s
Apr 18 13:10:32.271: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.308593184s
Apr 18 13:10:34.376: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.413352025s
Apr 18 13:10:36.481: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.518714931s
Apr 18 13:10:38.587: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Running", Reason="", readiness=true. Elapsed: 10.624613851s
Apr 18 13:10:40.693: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Running", Reason="", readiness=true. Elapsed: 12.73051684s
Apr 18 13:10:42.798: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Running", Reason="", readiness=true. Elapsed: 14.835486722s
Apr 18 13:10:44.903: INFO: Pod "azurefile-volume-tester-ht2pz": Phase="Failed", Reason="", readiness=false. Elapsed: 16.939953713s
STEP: Saw pod failure
Apr 18 13:10:44.903: INFO: Pod "azurefile-volume-tester-ht2pz" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 13:10:45.017: INFO: deleting Pod "azurefile-156"/"azurefile-volume-tester-ht2pz"
Apr 18 13:10:45.122: INFO: Pod azurefile-volume-tester-ht2pz 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 201 lines ...
Apr 18 13:11:55.830: INFO: PersistentVolumeClaim pvc-qctxf found but phase is Pending instead of Bound.
Apr 18 13:11:57.933: INFO: PersistentVolumeClaim pvc-qctxf found and phase=Bound (2.205044354s)
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 18 13:11:58.241: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-zd5sx" in namespace "azurefile-2546" to be "Succeeded or Failed"
Apr 18 13:11:58.343: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Pending", Reason="", readiness=false. Elapsed: 101.747351ms
Apr 18 13:12:00.445: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.203955802s
Apr 18 13:12:02.550: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309251999s
Apr 18 13:12:04.656: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.414667318s
Apr 18 13:12:06.761: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.519593484s
Apr 18 13:12:08.865: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Running", Reason="", readiness=true. Elapsed: 10.62419015s
Apr 18 13:12:10.971: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Running", Reason="", readiness=true. Elapsed: 12.730026981s
Apr 18 13:12:13.077: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Running", Reason="", readiness=true. Elapsed: 14.835870037s
Apr 18 13:12:15.183: INFO: Pod "azurefile-volume-tester-zd5sx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.942111606s
STEP: Saw pod success
Apr 18 13:12:15.183: INFO: Pod "azurefile-volume-tester-zd5sx" satisfied condition "Succeeded or Failed"
STEP: resizing the pvc
STEP: sleep 30s waiting for resize complete
STEP: checking the resizing result
STEP: checking the resizing PV result
STEP: checking the resizing azurefile result
Apr 18 13:12:45.965: INFO: deleting Pod "azurefile-2546"/"azurefile-volume-tester-zd5sx"
... skipping 302 lines ...
Apr 18 13:13:14.585: INFO: PersistentVolumeClaim pvc-d4lwm found but phase is Pending instead of Bound.
Apr 18 13:13:16.688: INFO: PersistentVolumeClaim pvc-d4lwm found and phase=Bound (2.205370124s)
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 18 13:13:16.996: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-cg4g9" in namespace "azurefile-9183" to be "Succeeded or Failed"
Apr 18 13:13:17.100: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 103.953651ms
Apr 18 13:13:19.206: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210037589s
Apr 18 13:13:21.312: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.315827989s
Apr 18 13:13:23.416: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.420356769s
Apr 18 13:13:25.532: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.535951438s
Apr 18 13:13:27.638: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 10.641887066s
Apr 18 13:13:29.743: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Pending", Reason="", readiness=false. Elapsed: 12.74710536s
Apr 18 13:13:31.849: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Running", Reason="", readiness=true. Elapsed: 14.852550501s
Apr 18 13:13:33.954: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Running", Reason="", readiness=true. Elapsed: 16.95804719s
Apr 18 13:13:36.061: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Running", Reason="", readiness=true. Elapsed: 19.064612821s
Apr 18 13:13:38.165: INFO: Pod "azurefile-volume-tester-cg4g9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 21.169087221s
STEP: Saw pod success
Apr 18 13:13:38.165: INFO: Pod "azurefile-volume-tester-cg4g9" satisfied condition "Succeeded or Failed"
Apr 18 13:13:38.165: INFO: deleting Pod "azurefile-9183"/"azurefile-volume-tester-cg4g9"
Apr 18 13:13:38.276: INFO: Pod azurefile-volume-tester-cg4g9 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-cg4g9 in namespace azurefile-9183
Apr 18 13:13:38.389: INFO: deleting PVC "azurefile-9183"/"pvc-d4lwm"
Apr 18 13:13:38.389: INFO: Deleting PersistentVolumeClaim "pvc-d4lwm"
... skipping 90 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 13:13:45 Check successfully
Apr 18 13:13:45.240: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 13:13:45 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 13:13:45 got output: azure-storage-account-f44687c98ac654d02829760-secret
, error: <nil>
2022/04/18 13:13:45 got storage account secret name: azure-storage-account-f44687c98ac654d02829760-secret
STEP: setting up the StorageClass
STEP: creating a StorageClass 
STEP: setting up the PVC and PV
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 13:13:45.869: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-q8qx9] to have phase Bound
Apr 18 13:13:45.970: INFO: PersistentVolumeClaim pvc-q8qx9 found and phase=Bound (100.944858ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 13:13:47.277: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-bjsmm" in namespace "azurefile-1968" to be "Succeeded or Failed"
Apr 18 13:13:47.383: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Pending", Reason="", readiness=false. Elapsed: 106.235107ms
Apr 18 13:13:49.485: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.208217829s
Apr 18 13:13:51.590: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.312902525s
Apr 18 13:13:53.696: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.41856821s
Apr 18 13:13:55.800: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522872079s
Apr 18 13:13:57.906: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Running", Reason="", readiness=true. Elapsed: 10.629012802s
Apr 18 13:14:00.012: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Running", Reason="", readiness=true. Elapsed: 12.735006821s
Apr 18 13:14:02.119: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Running", Reason="", readiness=true. Elapsed: 14.84199584s
Apr 18 13:14:04.224: INFO: Pod "azurefile-volume-tester-bjsmm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.947120073s
STEP: Saw pod success
Apr 18 13:14:04.224: INFO: Pod "azurefile-volume-tester-bjsmm" satisfied condition "Succeeded or Failed"
Apr 18 13:14:04.224: INFO: deleting Pod "azurefile-1968"/"azurefile-volume-tester-bjsmm"
Apr 18 13:14:04.340: INFO: Pod azurefile-volume-tester-bjsmm has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-bjsmm in namespace azurefile-1968
Apr 18 13:14:04.452: INFO: deleting PVC "azurefile-1968"/"pvc-q8qx9"
Apr 18 13:14:04.452: INFO: Deleting PersistentVolumeClaim "pvc-q8qx9"
... skipping 46 lines ...
Apr 18 13:14:32.186: INFO: PersistentVolumeClaim pvc-zcv8c found and phase=Bound (25.334181305s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 13:14:33.494: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-frxqs" in namespace "azurefile-4657" to be "Succeeded or Failed"
Apr 18 13:14:33.596: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Pending", Reason="", readiness=false. Elapsed: 101.87549ms
Apr 18 13:14:35.699: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205041665s
Apr 18 13:14:37.806: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Pending", Reason="", readiness=false. Elapsed: 4.311548646s
Apr 18 13:14:39.911: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Pending", Reason="", readiness=false. Elapsed: 6.416562142s
Apr 18 13:14:42.016: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Pending", Reason="", readiness=false. Elapsed: 8.521760534s
Apr 18 13:14:44.121: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Running", Reason="", readiness=true. Elapsed: 10.627086049s
Apr 18 13:14:46.228: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Running", Reason="", readiness=true. Elapsed: 12.733814482s
Apr 18 13:14:48.334: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Running", Reason="", readiness=true. Elapsed: 14.840177555s
Apr 18 13:14:50.440: INFO: Pod "azurefile-volume-tester-frxqs": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.946211116s
STEP: Saw pod success
Apr 18 13:14:50.440: INFO: Pod "azurefile-volume-tester-frxqs" satisfied condition "Succeeded or Failed"
Apr 18 13:14:50.440: INFO: deleting Pod "azurefile-4657"/"azurefile-volume-tester-frxqs"
Apr 18 13:14:50.551: INFO: Pod azurefile-volume-tester-frxqs has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-frxqs in namespace azurefile-4657
Apr 18 13:14:50.665: INFO: deleting PVC "azurefile-4657"/"pvc-zcv8c"
Apr 18 13:14:50.665: INFO: Deleting PersistentVolumeClaim "pvc-zcv8c"
... skipping 73 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 13:16:16 Check successfully
Apr 18 13:16:16.593: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 13:16:16 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 13:16:17 got output: azure-storage-account-f44687c98ac654d02829760-secret
, error: <nil>
2022/04/18 13:16:17 got storage account secret name: azure-storage-account-f44687c98ac654d02829760-secret
STEP: Successfully provisioned AzureFile volume: "capz-vcrgvu#f44687c98ac654d02829760#csi-inline-smb-volume##csi-inline-smb-volume"

STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 13:16:18.498: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-ghcfh" in namespace "azurefile-4162" to be "Succeeded or Failed"
Apr 18 13:16:18.600: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Pending", Reason="", readiness=false. Elapsed: 101.764121ms
Apr 18 13:16:20.704: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20551888s
Apr 18 13:16:22.810: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.311757541s
Apr 18 13:16:24.919: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.420713149s
Apr 18 13:16:27.025: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.52662406s
Apr 18 13:16:29.130: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Running", Reason="", readiness=true. Elapsed: 10.631876779s
Apr 18 13:16:31.236: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Running", Reason="", readiness=true. Elapsed: 12.738026049s
Apr 18 13:16:33.342: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Running", Reason="", readiness=true. Elapsed: 14.844120009s
Apr 18 13:16:35.448: INFO: Pod "azurefile-volume-tester-ghcfh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.950106895s
STEP: Saw pod success
Apr 18 13:16:35.448: INFO: Pod "azurefile-volume-tester-ghcfh" satisfied condition "Succeeded or Failed"
Apr 18 13:16:35.448: INFO: deleting Pod "azurefile-4162"/"azurefile-volume-tester-ghcfh"
Apr 18 13:16:35.560: INFO: Pod azurefile-volume-tester-ghcfh has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-ghcfh in namespace azurefile-4162
Apr 18 13:16:35.675: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "azurefile-4162" for this suite.
... skipping 43 lines ...
======================================================================================
2022/04/18 13:16:38 Check successfully
Apr 18 13:16:38.930: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: creating secret smbcreds in namespace azurefile-5320
2022/04/18 13:16:39 run script: test/utils/get_smb_svc_public_ip.sh
2022/04/18 13:16:39 got output: 20.90.216.200
, error: <nil>
2022/04/18 13:16:39 use server on Windows: 20.90.216.200
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 13:16:39.567: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4tgjv" in namespace "azurefile-5320" to be "Succeeded or Failed"
Apr 18 13:16:39.669: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Pending", Reason="", readiness=false. Elapsed: 101.996372ms
Apr 18 13:16:41.772: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204845746s
Apr 18 13:16:43.878: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.310825674s
Apr 18 13:16:45.984: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.416070855s
Apr 18 13:16:48.090: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522231129s
Apr 18 13:16:50.195: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Running", Reason="", readiness=true. Elapsed: 10.627748456s
Apr 18 13:16:52.301: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Running", Reason="", readiness=true. Elapsed: 12.733652489s
Apr 18 13:16:54.407: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Running", Reason="", readiness=true. Elapsed: 14.839603829s
Apr 18 13:16:56.512: INFO: Pod "azurefile-volume-tester-4tgjv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.944954002s
STEP: Saw pod success
Apr 18 13:16:56.512: INFO: Pod "azurefile-volume-tester-4tgjv" satisfied condition "Succeeded or Failed"
Apr 18 13:16:56.512: INFO: deleting Pod "azurefile-5320"/"azurefile-volume-tester-4tgjv"
Apr 18 13:16:56.624: INFO: Pod azurefile-volume-tester-4tgjv has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-4tgjv in namespace azurefile-5320
Apr 18 13:16:56.738: INFO: deleting Secret smbcreds
Apr 18 13:16:56.843: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
... skipping 181 lines ...
Platform: linux/amd64

Streaming logs below:
I0418 12:55:02.931831       1 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-linux) e2e-test
I0418 12:55:02.932175       1 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 12:55:02.940283       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 7 milliseconds
W0418 12:55:02.940515       1 azure.go:78] 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
I0418 12:55:02.940536       1 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 12:55:02.940546       1 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0418 12:55:02.940575       1 azure.go:101] read cloud config from file: /etc/kubernetes/azure.json successfully
I0418 12:55:02.941665       1 azure_auth.go:245] Using AzurePublicCloud environment
I0418 12:55:02.941720       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 12:55:02.941793       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 2840 lines ...
Platform: windows/amd64

Streaming logs below:
I0418 12:55:54.423101    6528 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-windows) e2e-test
I0418 12:55:54.434576    6528 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 12:55:54.457673    6528 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 21 milliseconds
W0418 12:55:54.461230    6528 azure.go:78] 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
I0418 12:55:54.461230    6528 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 12:55:54.461230    6528 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0418 12:55:54.461230    6528 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0418 12:55:54.465543    6528 azure_auth.go:245] Using AzurePublicCloud environment
I0418 12:55:54.466211    6528 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 12:55:54.466950    6528 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 35 lines ...
I0418 12:56:31.599775    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 12:56:31.599775    6528 utils.go:77] GRPC request: {}
I0418 12:56:31.599775    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 12:56:31.601705    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume
I0418 12:56:31.601740    6528 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-8081-file.csi.azure.com-preprovsioned-pv-nsg8z\\globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_id":"capz-vcrgvu#f44687c98ac654d02829760#pre-provisioned-readonly##pre-provisioned-readonly"}
I0418 12:56:31.605550    6528 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/default/secrets/azure-storage-account-f44687c98ac654d02829760-secret 404 Not Found in 3 milliseconds
I0418 12:56:31.605550    6528 azurefile.go:616] could not get account(f44687c98ac654d02829760) key from secret(azure-storage-account-f44687c98ac654d02829760-secret), error: could not get secret(azure-storage-account-f44687c98ac654d02829760-secret): secrets "azure-storage-account-f44687c98ac654d02829760-secret" not found, use cluster identity to get account key instead
(2022-04-18T12:56:31.6061514Z) INFO: REQUEST: POST https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token
User-Agent: Go/go1.18.1 (amd64-windows) go-autorest/adal/v1.0.0
Content-Type: application/x-www-form-urlencoded
(2022-04-18T12:56:31.9380788Z) INFO: RESPONSE: 200 https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token
Expires: -1
X-Ms-Request-Id: b02a68dc-7de3-44b0-ad3e-88bdb79fb200
... skipping 140 lines ...
I0418 13:03:13.011703    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:03:13.011703    6528 utils.go:77] GRPC request: {}
I0418 13:03:13.015585    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:03:13.017921    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume
I0418 13:03:13.017921    6528 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-2540-file.csi.azure.com-preprovsioned-pv-ffmpb\\globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_id":"capz-vcrgvu#f44687c98ac654d02829760#pre-provisioned-multiple-pods##pre-provisioned-multiple-pods1"}
I0418 13:03:13.026199    6528 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/default/secrets/azure-storage-account-f44687c98ac654d02829760-secret 404 Not Found in 7 milliseconds
I0418 13:03:13.026199    6528 azurefile.go:616] could not get account(f44687c98ac654d02829760) key from secret(azure-storage-account-f44687c98ac654d02829760-secret), error: could not get secret(azure-storage-account-f44687c98ac654d02829760-secret): secrets "azure-storage-account-f44687c98ac654d02829760-secret" not found, use cluster identity to get account key instead
(2022-04-18T13:03:13.0287653Z) INFO: REQUEST: POST https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vcrgvu/providers/Microsoft.Storage/storageAccounts/f44687c98ac654d02829760/listKeys?api-version=2021-02-01
User-Agent: Go/go1.18.1 (amd64-windows) go-autorest/v14.2.1 file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-windows) e2e-test
Authorization: **REDACTED**
Content-Type: application/json; charset=utf-8
(2022-04-18T13:03:13.2363873Z) INFO: RESPONSE: 200 https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-vcrgvu/providers/Microsoft.Storage/storageAccounts/f44687c98ac654d02829760/listKeys?api-version=2021-02-01
Strict-Transport-Security: max-age=31536000; includeSubDomains
... skipping 559 lines ...
I0418 13:07:52.144645    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:52.145543    6528 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:52.145567    6528 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:52.146296    6528 safe_mounter_windows.go:70] SMBMount: remote path: \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:52.146324    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148
I0418 13:07:52.146833    6528 safe_mounter_windows.go:97] begin to mount \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
E0418 13:07:56.781380    6528 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-vcrgvu#fa2135a3def0f46e68da071#pvc-1bb5187b-6cd2-48b7-b425-83412f075148#) mount "\\\\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
I0418 13:07:57.375572    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:07:57.375572    6528 utils.go:77] GRPC request: {}
I0418 13:07:57.375572    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:07:57.378123    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:07:57.378123    6528 utils.go:77] GRPC request: {}
I0418 13:07:57.378123    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 8 lines ...
I0418 13:07:57.382808    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:57.383272    6528 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:57.383272    6528 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:57.383808    6528 safe_mounter_windows.go:70] SMBMount: remote path: \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:07:57.383808    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148
I0418 13:07:57.384193    6528 safe_mounter_windows.go:97] begin to mount \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
E0418 13:07:59.646536    6528 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-vcrgvu#fa2135a3def0f46e68da071#pvc-1bb5187b-6cd2-48b7-b425-83412f075148#) mount "\\\\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
I0418 13:08:00.748886    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:00.748886    6528 utils.go:77] GRPC request: {}
I0418 13:08:00.748886    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:08:00.752150    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:00.752150    6528 utils.go:77] GRPC request: {}
I0418 13:08:00.752150    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 8 lines ...
I0418 13:08:00.756158    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:00.756158    6528 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:00.756158    6528 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:00.756889    6528 safe_mounter_windows.go:70] SMBMount: remote path: \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:00.756889    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148
I0418 13:08:00.757532    6528 safe_mounter_windows.go:97] begin to mount \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
E0418 13:08:02.997139    6528 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-vcrgvu#fa2135a3def0f46e68da071#pvc-1bb5187b-6cd2-48b7-b425-83412f075148#) mount "\\\\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
I0418 13:08:05.074855    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:05.074882    6528 utils.go:77] GRPC request: {}
I0418 13:08:05.074940    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:08:05.076767    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:05.076767    6528 utils.go:77] GRPC request: {}
I0418 13:08:05.076767    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 8 lines ...
I0418 13:08:05.083614    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:05.083614    6528 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:05.083614    6528 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:05.084312    6528 safe_mounter_windows.go:70] SMBMount: remote path: \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:05.084312    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148
I0418 13:08:05.085066    6528 safe_mounter_windows.go:97] begin to mount \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
E0418 13:08:07.298413    6528 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-vcrgvu#fa2135a3def0f46e68da071#pvc-1bb5187b-6cd2-48b7-b425-83412f075148#) mount "\\\\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
I0418 13:08:08.579890    6528 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 13:08:08.579890    6528 utils.go:77] GRPC request: {}
I0418 13:08:08.580480    6528 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 13:08:11.329090    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:11.330058    6528 utils.go:77] GRPC request: {}
I0418 13:08:11.330058    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 11 lines ...
I0418 13:08:11.344028    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:11.344654    6528 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:11.344654    6528 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:11.344763    6528 safe_mounter_windows.go:70] SMBMount: remote path: \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:11.344763    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148
I0418 13:08:11.345593    6528 safe_mounter_windows.go:97] begin to mount \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
E0418 13:08:13.640728    6528 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-vcrgvu#fa2135a3def0f46e68da071#pvc-1bb5187b-6cd2-48b7-b425-83412f075148#) mount "\\\\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
I0418 13:08:21.689627    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:21.689627    6528 utils.go:77] GRPC request: {}
I0418 13:08:21.689627    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:08:21.691431    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:21.691431    6528 utils.go:77] GRPC request: {}
I0418 13:08:21.691431    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 8 lines ...
I0418 13:08:21.696130    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:21.696743    6528 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:21.696790    6528 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:21.697164    6528 safe_mounter_windows.go:70] SMBMount: remote path: \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
I0418 13:08:21.697164    6528 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148
I0418 13:08:21.698001    6528 safe_mounter_windows.go:97] begin to mount \\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\pvc-1bb5187b-6cd2-48b7-b425-83412f075148 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\globalmount
E0418 13:08:23.949689    6528 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-vcrgvu#fa2135a3def0f46e68da071#pvc-1bb5187b-6cd2-48b7-b425-83412f075148#) mount "\\\\fa2135a3def0f46e68da071.privatelink.file.core.windows.net\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-1bb5187b-6cd2-48b7-b425-83412f075148\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
I0418 13:08:38.594348    6528 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 13:08:38.594348    6528 utils.go:77] GRPC request: {}
I0418 13:08:38.594348    6528 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 13:08:40.018257    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:08:40.018257    6528 utils.go:77] GRPC request: {}
I0418 13:08:40.018257    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 1160 lines ...
I0418 13:16:18.783299    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:16:18.783299    6528 utils.go:77] GRPC request: {}
I0418 13:16:18.783299    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:16:18.786112    6528 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0418 13:16:18.786112    6528 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\a5c65cf0-470a-4580-a8b4-1be1fff358fd\\volumes\\kubernetes.io~csi\\test-volume-1\\mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/ephemeral":"true","csi.storage.k8s.io/pod.name":"azurefile-volume-tester-ghcfh","csi.storage.k8s.io/pod.namespace":"azurefile-4162","csi.storage.k8s.io/pod.uid":"a5c65cf0-470a-4580-a8b4-1be1fff358fd","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"azure-storage-account-f44687c98ac654d02829760-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-7125e237c418ac30d5f3c9044c1a26ce25a8ab83859f524526f6120064a81f87"}
I0418 13:16:18.786918    6528 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-7125e237c418ac30d5f3c9044c1a26ce25a8ab83859f524526f6120064a81f87) mount on c:\var\lib\kubelet\pods\a5c65cf0-470a-4580-a8b4-1be1fff358fd\volumes\kubernetes.io~csi\test-volume-1\mount, VolumeContext: map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-ghcfh csi.storage.k8s.io/pod.namespace:azurefile-4162 csi.storage.k8s.io/pod.uid:a5c65cf0-470a-4580-a8b4-1be1fff358fd csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f44687c98ac654d02829760-secret secretnamespace:azurefile-4162 server: shareName:csi-inline-smb-volume storageaccount:]
W0418 13:16:18.789363    6528 azurefile.go:546] parsing volumeID(csi-7125e237c418ac30d5f3c9044c1a26ce25a8ab83859f524526f6120064a81f87) return with error: error parsing volume id: "csi-7125e237c418ac30d5f3c9044c1a26ce25a8ab83859f524526f6120064a81f87", should at least contain two #
I0418 13:16:18.797152    6528 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-4162/secrets/azure-storage-account-f44687c98ac654d02829760-secret 200 OK in 7 milliseconds
I0418 13:16:18.798292    6528 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\a5c65cf0-470a-4580-a8b4-1be1fff358fd\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-7125e237c418ac30d5f3c9044c1a26ce25a8ab83859f524526f6120064a81f87) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-ghcfh csi.storage.k8s.io/pod.namespace:azurefile-4162 csi.storage.k8s.io/pod.uid:a5c65cf0-470a-4580-a8b4-1be1fff358fd csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f44687c98ac654d02829760-secret secretnamespace:azurefile-4162 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\f44687c98ac654d02829760]) volumeMountGroup()
I0418 13:16:18.798292    6528 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\a5c65cf0-470a-4580-a8b4-1be1fff358fd\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 13:16:18.798292    6528 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\a5c65cf0-470a-4580-a8b4-1be1fff358fd\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 13:16:18.800078    6528 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\a5c65cf0-470a-4580-a8b4-1be1fff358fd\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 13:16:18.800349    6528 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\a5c65cf0-470a-4580-a8b4-1be1fff358fd\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 20 lines ...
I0418 13:16:39.798254    6528 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 13:16:39.798297    6528 utils.go:77] GRPC request: {}
I0418 13:16:39.798379    6528 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 13:16:39.799815    6528 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0418 13:16:39.799838    6528 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\842a261a-313c-4690-84c4-fae2cb05c9bb\\volumes\\kubernetes.io~csi\\test-volume-1\\mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/ephemeral":"true","csi.storage.k8s.io/pod.name":"azurefile-volume-tester-4tgjv","csi.storage.k8s.io/pod.namespace":"azurefile-5320","csi.storage.k8s.io/pod.uid":"842a261a-313c-4690-84c4-fae2cb05c9bb","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"smbcreds","server":"20.90.216.200","shareName":"share"},"volume_id":"csi-2e23d740188c6d4d42407bc209b8c87ac7f7125ccc634cd19587b01b29ef0903"}
I0418 13:16:39.800003    6528 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-2e23d740188c6d4d42407bc209b8c87ac7f7125ccc634cd19587b01b29ef0903) mount on c:\var\lib\kubelet\pods\842a261a-313c-4690-84c4-fae2cb05c9bb\volumes\kubernetes.io~csi\test-volume-1\mount, VolumeContext: map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-4tgjv csi.storage.k8s.io/pod.namespace:azurefile-5320 csi.storage.k8s.io/pod.uid:842a261a-313c-4690-84c4-fae2cb05c9bb csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-5320 server:20.90.216.200 shareName:share storageaccount:]
W0418 13:16:39.800074    6528 azurefile.go:546] parsing volumeID(csi-2e23d740188c6d4d42407bc209b8c87ac7f7125ccc634cd19587b01b29ef0903) return with error: error parsing volume id: "csi-2e23d740188c6d4d42407bc209b8c87ac7f7125ccc634cd19587b01b29ef0903", should at least contain two #
I0418 13:16:39.803293    6528 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-5320/secrets/smbcreds 200 OK in 3 milliseconds
I0418 13:16:39.803293    6528 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\842a261a-313c-4690-84c4-fae2cb05c9bb\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-2e23d740188c6d4d42407bc209b8c87ac7f7125ccc634cd19587b01b29ef0903) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-4tgjv csi.storage.k8s.io/pod.namespace:azurefile-5320 csi.storage.k8s.io/pod.uid:842a261a-313c-4690-84c4-fae2cb05c9bb csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-5320 server:20.90.216.200 shareName:share storageaccount:]) mountflags([]) mountOptions([AZURE\USERNAME]) volumeMountGroup()
I0418 13:16:39.803293    6528 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\842a261a-313c-4690-84c4-fae2cb05c9bb\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 13:16:39.803293    6528 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\842a261a-313c-4690-84c4-fae2cb05c9bb\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 13:16:39.804794    6528 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\842a261a-313c-4690-84c4-fae2cb05c9bb\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 13:16:39.804987    6528 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\842a261a-313c-4690-84c4-fae2cb05c9bb\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 121 lines ...
Platform: windows/amd64

Streaming logs below:
I0418 12:55:54.914148    5756 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-windows) e2e-test
I0418 12:55:54.926092    5756 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 12:55:54.958002    5756 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 21 milliseconds
W0418 12:55:54.959340    5756 azure.go:78] 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
I0418 12:55:54.959340    5756 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 12:55:54.959340    5756 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0418 12:55:54.959864    5756 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0418 12:55:54.962791    5756 azure_auth.go:245] Using AzurePublicCloud environment
I0418 12:55:54.963356    5756 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 12:55:54.965213    5756 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 574 lines ...

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


Summarizing 1 Failure:

[Fail] Pre-Provisioned [It] should use a pre-provisioned volume and mount it as readOnly in a pod [file.csi.azure.com] [Windows] 
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/pre_provisioned_read_only_volume_tester.go:59

Ran 20 of 34 Specs in 1420.229 seconds
FAIL! -- 19 Passed | 1 Failed | 0 Pending | 14 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 (1420.24s)
FAIL
FAIL	sigs.k8s.io/azurefile-csi-driver/test/e2e	1420.338s
FAIL
make: *** [Makefile:85: 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 97 lines ...