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-21 03:51
Elapsed49m27s
Revision1ecf7e2b24335790fae9e49b3535eab947e6ad78
Refs 988

Test Failures

AzureFile CSI Driver End-to-End Tests Dynamic Provisioning should create a volume on demand with mount options [kubernetes.io/azure-file] [file.csi.azure.com] [Windows] 10m34s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=AzureFile\sCSI\sDriver\sEnd\-to\-End\sTests\sDynamic\sProvisioning\sshould\screate\sa\svolume\son\sdemand\swith\smount\soptions\s\[kubernetes\.io\/azure\-file\]\s\[file\.csi\.azure\.com\]\s\[Windows\]$'
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:104
Unexpected error:
    <*errors.errorString | 0xc000518c30>: {
        s: "pod \"azurefile-volume-tester-gbrmv\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +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-21 04:09:57 +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-21 04:09:57 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.221.196 PodIPs:[{IP:192.168.221.196}] StartTime:2022-04-21 04:09:57 +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://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014 Started:0xc00094f2a8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
    }
    pod "azurefile-volume-tester-gbrmv" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +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-21 04:09:57 +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-21 04:09:57 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.221.196 PodIPs:[{IP:192.168.221.196}] StartTime:2022-04-21 04:09:57 +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://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014 Started:0xc00094f2a8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
occurred
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:691
				
				Click to see stdout/stderrfrom junit_01.xml

Find azurefile-volume-tester-gbrmv mentions in log files | View test history on testgrid

Show 19 Passed Tests
Show 14 Skipped Tests

Error lines from build-log.txt

... skipping 672 lines ...
certificate.cert-manager.io "selfsigned-cert" deleted
# Create secret for AzureClusterIdentity
./hack/create-identity-secret.sh
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
make[2]: Nothing to be done for 'kubectl'.
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Error from server (NotFound): secrets "cluster-identity-secret" not found
secret/cluster-identity-secret created
secret/cluster-identity-secret labeled
# Deploy CAPI
curl --retry 3 -sSL https://github.com/kubernetes-sigs/cluster-api/releases/download/v1.1.2/cluster-api-components.yaml | /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/envsubst-v2.0.0-20210730161058-179042472c46 | kubectl apply -f -
namespace/capi-system created
customresourcedefinition.apiextensions.k8s.io/clusterclasses.cluster.x-k8s.io created
... skipping 129 lines ...
# Wait for the kubeconfig to become available.
timeout --foreground 300 bash -c "while ! kubectl get secrets | grep capz-wu3n7j-kubeconfig; do sleep 1; done"
capz-wu3n7j-kubeconfig                 cluster.x-k8s.io/secret               1      1s
# Get kubeconfig and store it locally.
kubectl get secrets capz-wu3n7j-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-wu3n7j-control-plane-8x9zb   NotReady   control-plane,master   13s   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-wu3n-6ctgs condition met
node/capz-wu3n-njpbf condition met
... skipping 1026 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 147 lines ...
Driver Version: N/A
Git Commit: N/A
Go Version: go1.18.1
Platform: linux/amd64

Streaming logs below:
W0421 04:07:50.995266   36340 azure.go:78] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
STEP: Building a namespace api object, basename azurefile
I0421 04:07:51.013448   36340 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0421 04:07:51.013485   36340 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0421 04:07:51.013491   36340 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0421 04:07:51.013495   36340 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0421 04:07:51.013499   36340 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
... skipping 121 lines ...
Apr 21 04:09:55.106: INFO: PersistentVolumeClaim pvc-cjj7x found but phase is Pending instead of Bound.
Apr 21 04:09:57.138: INFO: PersistentVolumeClaim pvc-cjj7x found and phase=Bound (1m37.64121106s)
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 21 04:09:57.236: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-gbrmv" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 21 04:09:57.268: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 31.633182ms
Apr 21 04:09:59.303: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066737733s
Apr 21 04:10:01.337: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.100714209s
Apr 21 04:10:03.370: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133579044s
Apr 21 04:10:05.403: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166930793s
Apr 21 04:10:07.436: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.199943322s
... skipping 248 lines ...
Apr 21 04:18:34.079: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8m36.842382095s
Apr 21 04:18:36.114: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8m38.877455908s
Apr 21 04:18:38.150: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8m40.913876902s
Apr 21 04:18:40.185: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8m42.948591744s
Apr 21 04:18:42.221: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8m44.985112934s
Apr 21 04:18:44.255: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Pending", Reason="", readiness=false. Elapsed: 8m47.019257268s
Apr 21 04:18:46.290: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Failed", Reason="", readiness=false. Elapsed: 8m49.054039538s
STEP: hit error(pod "azurefile-volume-tester-gbrmv" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +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-21 04:09:57 +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-21 04:09:57 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.221.196 PodIPs:[{IP:192.168.221.196}] StartTime:2022-04-21 04:09:57 +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://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014 Started:0xc00094ed38}] QOSClass:BestEffort EphemeralContainerStatuses:[]}) in first run, give another try
Apr 21 04:18:46.291: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-gbrmv" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 21 04:18:46.325: INFO: Pod "azurefile-volume-tester-gbrmv": Phase="Failed", Reason="", readiness=false. Elapsed: 34.11247ms
Apr 21 04:18:46.325: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-gbrmv"
Apr 21 04:18:46.380: INFO: Pod azurefile-volume-tester-gbrmv has the following logs: 
STEP: Deleting pod azurefile-volume-tester-gbrmv in namespace azurefile-2540
Apr 21 04:18:46.421: INFO: deleting PVC "azurefile-2540"/"pvc-cjj7x"
Apr 21 04:18:46.421: INFO: Deleting PersistentVolumeClaim "pvc-cjj7x"
STEP: waiting for claim's PV "pvc-219b8c3b-f4c9-487c-8501-35d9ce960c97" to be deleted
... skipping 6 lines ...
STEP: Collecting events from namespace "azurefile-2540".
STEP: Found 12 events.
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:08:19 +0000 UTC - event for pvc-cjj7x: {file.csi.azure.com_capz-wu3n7j-md-0-h5bx4_0a16be51-4249-4c6c-b9e2-1d8032487f87 } Provisioning: External provisioner is provisioning volume for claim "azurefile-2540/pvc-cjj7x"
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:08:19 +0000 UTC - event for pvc-cjj7x: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:09:55 +0000 UTC - event for pvc-cjj7x: {file.csi.azure.com_capz-wu3n7j-md-0-h5bx4_0a16be51-4249-4c6c-b9e2-1d8032487f87 } ProvisioningSucceeded: Successfully provisioned volume pvc-219b8c3b-f4c9-487c-8501-35d9ce960c97
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:09:57 +0000 UTC - event for azurefile-volume-tester-gbrmv: {default-scheduler } Scheduled: Successfully assigned azurefile-2540/azurefile-volume-tester-gbrmv to capz-wu3n-6ctgs
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:09:57 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} FailedMount: MountVolume.MountDevice failed for volume "pvc-219b8c3b-f4c9-487c-8501-35d9ce960c97" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:11:13 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:16:44 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 5m30.633751s
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:16:44 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Created: Created container volume-tester
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:18:44 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:18:44 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Failed: Error: context deadline exceeded
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:18:50 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Started: Started container volume-tester
Apr 21 04:18:51.690: INFO: At 2022-04-21 04:18:50 +0000 UTC - event for azurefile-volume-tester-gbrmv: {kubelet capz-wu3n-6ctgs} Killing: Stopping container volume-tester
Apr 21 04:18:51.722: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 21 04:18:51.722: INFO: 
Apr 21 04:18:51.766: INFO: 
Logging node info for node capz-wu3n-6ctgs
... skipping 114 lines ...
• Failure [634.527 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create a volume on demand with mount options [kubernetes.io/azure-file] [file.csi.azure.com] [Windows] [It]
  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:104

  Unexpected error:
      <*errors.errorString | 0xc000518c30>: {
          s: "pod \"azurefile-volume-tester-gbrmv\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +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-21 04:09:57 +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-21 04:09:57 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.221.196 PodIPs:[{IP:192.168.221.196}] StartTime:2022-04-21 04:09:57 +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://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014 Started:0xc00094f2a8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
      }
      pod "azurefile-volume-tester-gbrmv" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-21 04:09:57 +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-21 04:09:57 +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-21 04:09:57 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.221.196 PodIPs:[{IP:192.168.221.196}] StartTime:2022-04-21 04:09:57 +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://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://f34405ec9383d0af41d58d7872f41f77552f5abf44015d252db39d21336e3014 Started:0xc00094f2a8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:691
------------------------------
Dynamic Provisioning 
  should create a pod with volume mount subpath [file.csi.azure.com] [Windows]
... skipping 26 lines ...
Apr 21 04:19:12.596: INFO: PersistentVolumeClaim pvc-nj8bq found but phase is Pending instead of Bound.
Apr 21 04:19:14.630: INFO: PersistentVolumeClaim pvc-nj8bq found and phase=Bound (20.368058703s)
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 21 04:19:14.729: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-26v4k" in namespace "azurefile-4728" to be "Succeeded or Failed"
Apr 21 04:19:14.762: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Pending", Reason="", readiness=false. Elapsed: 33.013778ms
Apr 21 04:19:16.795: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066218704s
Apr 21 04:19:18.828: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098884262s
Apr 21 04:19:20.863: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.13380637s
Apr 21 04:19:22.897: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.168160178s
Apr 21 04:19:24.931: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.202426431s
... skipping 3 lines ...
Apr 21 04:19:33.066: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Running", Reason="", readiness=true. Elapsed: 18.33705021s
Apr 21 04:19:35.102: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Running", Reason="", readiness=true. Elapsed: 20.373333328s
Apr 21 04:19:37.137: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Running", Reason="", readiness=true. Elapsed: 22.407706071s
Apr 21 04:19:39.170: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Running", Reason="", readiness=true. Elapsed: 24.441142663s
Apr 21 04:19:41.206: INFO: Pod "azurefile-volume-tester-26v4k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 26.476805778s
STEP: Saw pod success
Apr 21 04:19:41.206: INFO: Pod "azurefile-volume-tester-26v4k" satisfied condition "Succeeded or Failed"
Apr 21 04:19:41.206: INFO: deleting Pod "azurefile-4728"/"azurefile-volume-tester-26v4k"
Apr 21 04:19:41.247: INFO: Pod azurefile-volume-tester-26v4k has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-26v4k in namespace azurefile-4728
Apr 21 04:19:41.296: INFO: deleting PVC "azurefile-4728"/"pvc-nj8bq"
Apr 21 04:19:41.296: INFO: Deleting PersistentVolumeClaim "pvc-nj8bq"
... skipping 117 lines ...
Apr 21 04:20:51.395: INFO: PersistentVolumeClaim pvc-d9cln found but phase is Pending instead of Bound.
Apr 21 04:20:53.428: INFO: PersistentVolumeClaim pvc-d9cln found and phase=Bound (22.407851056s)
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 21 04:20:53.527: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-2vnhv" in namespace "azurefile-2790" to be "Error status code"
Apr 21 04:20:53.584: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 56.794836ms
Apr 21 04:20:55.619: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.09243629s
Apr 21 04:20:57.699: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.172539714s
Apr 21 04:20:59.734: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207604107s
Apr 21 04:21:01.769: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.242138006s
Apr 21 04:21:03.803: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.27596431s
Apr 21 04:21:05.837: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Pending", Reason="", readiness=false. Elapsed: 12.310284156s
Apr 21 04:21:07.872: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Running", Reason="", readiness=true. Elapsed: 14.345015117s
Apr 21 04:21:09.906: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Running", Reason="", readiness=true. Elapsed: 16.379416624s
Apr 21 04:21:11.940: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Running", Reason="", readiness=true. Elapsed: 18.413385538s
Apr 21 04:21:13.974: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Running", Reason="", readiness=true. Elapsed: 20.447599166s
Apr 21 04:21:16.011: INFO: Pod "azurefile-volume-tester-2vnhv": Phase="Failed", Reason="", readiness=false. Elapsed: 22.484386661s
STEP: Saw pod failure
Apr 21 04:21:16.011: INFO: Pod "azurefile-volume-tester-2vnhv" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 21 04:21:16.057: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-2vnhv"
Apr 21 04:21:16.094: INFO: Pod azurefile-volume-tester-2vnhv 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 21 04:22:37.189: INFO: PersistentVolumeClaim pvc-979hj found but phase is Pending instead of Bound.
Apr 21 04:22:39.223: INFO: PersistentVolumeClaim pvc-979hj found and phase=Bound (2.065786494s)
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 21 04:22:39.323: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-fm828" in namespace "azurefile-4538" to be "Succeeded or Failed"
Apr 21 04:22:39.359: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 35.800817ms
Apr 21 04:22:41.396: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 2.073356039s
Apr 21 04:22:43.430: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 4.10672579s
Apr 21 04:22:45.463: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 6.140553505s
Apr 21 04:22:47.499: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 8.175850614s
Apr 21 04:22:49.533: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210022951s
Apr 21 04:22:51.567: INFO: Pod "azurefile-volume-tester-fm828": Phase="Pending", Reason="", readiness=false. Elapsed: 12.243625705s
Apr 21 04:22:53.602: INFO: Pod "azurefile-volume-tester-fm828": Phase="Running", Reason="", readiness=true. Elapsed: 14.279166276s
Apr 21 04:22:55.636: INFO: Pod "azurefile-volume-tester-fm828": Phase="Running", Reason="", readiness=true. Elapsed: 16.313217808s
Apr 21 04:22:57.674: INFO: Pod "azurefile-volume-tester-fm828": Phase="Running", Reason="", readiness=true. Elapsed: 18.35118668s
Apr 21 04:22:59.707: INFO: Pod "azurefile-volume-tester-fm828": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.384441185s
STEP: Saw pod success
Apr 21 04:22:59.707: INFO: Pod "azurefile-volume-tester-fm828" 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 21 04:23:30.285: INFO: deleting Pod "azurefile-4538"/"azurefile-volume-tester-fm828"
... skipping 303 lines ...
Apr 21 04:23:51.861: INFO: PersistentVolumeClaim pvc-mb6vx found but phase is Pending instead of Bound.
Apr 21 04:23:53.899: INFO: PersistentVolumeClaim pvc-mb6vx found and phase=Bound (2.072057718s)
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 21 04:23:53.997: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-kqpc6" in namespace "azurefile-7726" to be "Succeeded or Failed"
Apr 21 04:23:54.031: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Pending", Reason="", readiness=false. Elapsed: 34.097737ms
Apr 21 04:23:56.067: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069485119s
Apr 21 04:23:58.101: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.104169485s
Apr 21 04:24:00.136: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.138529553s
Apr 21 04:24:02.170: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.172388939s
Apr 21 04:24:04.204: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206700268s
... skipping 3 lines ...
Apr 21 04:24:12.342: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Running", Reason="", readiness=true. Elapsed: 18.345219843s
Apr 21 04:24:14.377: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Running", Reason="", readiness=true. Elapsed: 20.379576985s
Apr 21 04:24:16.413: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Running", Reason="", readiness=true. Elapsed: 22.415612273s
Apr 21 04:24:18.447: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Running", Reason="", readiness=true. Elapsed: 24.449404413s
Apr 21 04:24:20.480: INFO: Pod "azurefile-volume-tester-kqpc6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 26.483228422s
STEP: Saw pod success
Apr 21 04:24:20.481: INFO: Pod "azurefile-volume-tester-kqpc6" satisfied condition "Succeeded or Failed"
Apr 21 04:24:20.481: INFO: deleting Pod "azurefile-7726"/"azurefile-volume-tester-kqpc6"
Apr 21 04:24:20.555: INFO: Pod azurefile-volume-tester-kqpc6 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-kqpc6 in namespace azurefile-7726
Apr 21 04:24:20.601: INFO: deleting PVC "azurefile-7726"/"pvc-mb6vx"
Apr 21 04:24:20.601: INFO: Deleting PersistentVolumeClaim "pvc-mb6vx"
... skipping 96 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/21 04:24:53 Check successfully
Apr 21 04:24:53.216: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/21 04:24:53 run script: test/utils/get_storage_account_secret_name.sh
2022/04/21 04:24:53 got output: azure-storage-account-fe0adf6af95b24b319cea4d-secret
, error: <nil>
2022/04/21 04:24:53 got storage account secret name: azure-storage-account-fe0adf6af95b24b319cea4d-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 21 04:24:53.519: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-kf4f9] to have phase Bound
Apr 21 04:24:53.550: INFO: PersistentVolumeClaim pvc-kf4f9 found but phase is Pending instead of Bound.
Apr 21 04:24:55.582: INFO: PersistentVolumeClaim pvc-kf4f9 found and phase=Bound (2.063482733s)
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 21 04:24:55.682: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-6d64q" in namespace "azurefile-1387" to be "Succeeded or Failed"
Apr 21 04:24:55.714: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 32.258468ms
Apr 21 04:24:57.757: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.075040415s
Apr 21 04:24:59.791: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.1089613s
Apr 21 04:25:01.825: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.142916784s
Apr 21 04:25:03.861: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.178977424s
Apr 21 04:25:05.897: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 10.214363194s
Apr 21 04:25:07.930: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Pending", Reason="", readiness=false. Elapsed: 12.247773822s
Apr 21 04:25:09.965: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Running", Reason="", readiness=true. Elapsed: 14.282752682s
Apr 21 04:25:11.998: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Running", Reason="", readiness=true. Elapsed: 16.315620917s
Apr 21 04:25:14.031: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Running", Reason="", readiness=true. Elapsed: 18.349059766s
Apr 21 04:25:16.064: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.381606696s
STEP: Saw pod success
Apr 21 04:25:16.064: INFO: Pod "azurefile-volume-tester-6d64q" satisfied condition "Succeeded or Failed"
Apr 21 04:25:16.064: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-6d64q" in namespace "azurefile-1387" to be "Succeeded or Failed"
Apr 21 04:25:16.096: INFO: Pod "azurefile-volume-tester-6d64q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 32.262166ms
STEP: Saw pod success
Apr 21 04:25:16.096: INFO: Pod "azurefile-volume-tester-6d64q" satisfied condition "Succeeded or Failed"
Apr 21 04:25:16.096: INFO: deleting Pod "azurefile-1387"/"azurefile-volume-tester-6d64q"
Apr 21 04:25:16.143: INFO: Pod azurefile-volume-tester-6d64q has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-6d64q in namespace azurefile-1387
Apr 21 04:25:16.189: INFO: deleting PVC "azurefile-1387"/"pvc-kf4f9"
Apr 21 04:25:16.189: INFO: Deleting PersistentVolumeClaim "pvc-kf4f9"
... skipping 44 lines ...
Apr 21 04:25:40.453: INFO: PersistentVolumeClaim pvc-lbkkp found but phase is Pending instead of Bound.
Apr 21 04:25:42.487: INFO: PersistentVolumeClaim pvc-lbkkp found and phase=Bound (20.36997564s)
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 21 04:25:42.585: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7jlfh" in namespace "azurefile-4547" to be "Succeeded or Failed"
Apr 21 04:25:42.625: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 40.136278ms
Apr 21 04:25:44.657: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.072750338s
Apr 21 04:25:46.691: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.106757279s
Apr 21 04:25:48.724: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.139649964s
Apr 21 04:25:50.761: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.175904576s
Apr 21 04:25:52.794: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208975628s
Apr 21 04:25:54.827: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Pending", Reason="", readiness=false. Elapsed: 12.242443863s
Apr 21 04:25:56.862: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Running", Reason="", readiness=true. Elapsed: 14.277558668s
Apr 21 04:25:58.895: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Running", Reason="", readiness=true. Elapsed: 16.310740277s
Apr 21 04:26:00.930: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Running", Reason="", readiness=true. Elapsed: 18.345659666s
Apr 21 04:26:02.964: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.379182894s
STEP: Saw pod success
Apr 21 04:26:02.964: INFO: Pod "azurefile-volume-tester-7jlfh" satisfied condition "Succeeded or Failed"
Apr 21 04:26:02.964: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7jlfh" in namespace "azurefile-4547" to be "Succeeded or Failed"
Apr 21 04:26:02.998: INFO: Pod "azurefile-volume-tester-7jlfh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 34.511498ms
STEP: Saw pod success
Apr 21 04:26:02.998: INFO: Pod "azurefile-volume-tester-7jlfh" satisfied condition "Succeeded or Failed"
Apr 21 04:26:02.998: INFO: deleting Pod "azurefile-4547"/"azurefile-volume-tester-7jlfh"
Apr 21 04:26:03.041: INFO: Pod azurefile-volume-tester-7jlfh has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-7jlfh in namespace azurefile-4547
Apr 21 04:26:03.085: INFO: deleting PVC "azurefile-4547"/"pvc-lbkkp"
Apr 21 04:26:03.085: INFO: Deleting PersistentVolumeClaim "pvc-lbkkp"
... skipping 75 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/21 04:27:28 Check successfully
Apr 21 04:27:28.082: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/21 04:27:28 run script: test/utils/get_storage_account_secret_name.sh
2022/04/21 04:27:28 got output: azure-storage-account-fe0adf6af95b24b319cea4d-secret
, error: <nil>
2022/04/21 04:27:28 got storage account secret name: azure-storage-account-fe0adf6af95b24b319cea4d-secret
STEP: Successfully provisioned AzureFile volume: "capz-wu3n7j#fe0adf6af95b24b319cea4d#csi-inline-smb-volume##csi-inline-smb-volume"

STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 21 04:27:29.277: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-77g67" in namespace "azurefile-4801" to be "Succeeded or Failed"
Apr 21 04:27:29.309: INFO: Pod "azurefile-volume-tester-77g67": Phase="Pending", Reason="", readiness=false. Elapsed: 31.557424ms
Apr 21 04:27:31.343: INFO: Pod "azurefile-volume-tester-77g67": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066155731s
Apr 21 04:27:33.377: INFO: Pod "azurefile-volume-tester-77g67": Phase="Pending", Reason="", readiness=false. Elapsed: 4.100094562s
Apr 21 04:27:35.411: INFO: Pod "azurefile-volume-tester-77g67": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133625349s
Apr 21 04:27:37.447: INFO: Pod "azurefile-volume-tester-77g67": Phase="Pending", Reason="", readiness=false. Elapsed: 8.169530153s
Apr 21 04:27:39.480: INFO: Pod "azurefile-volume-tester-77g67": Phase="Pending", Reason="", readiness=false. Elapsed: 10.203343952s
Apr 21 04:27:41.516: INFO: Pod "azurefile-volume-tester-77g67": Phase="Running", Reason="", readiness=true. Elapsed: 12.238569362s
Apr 21 04:27:43.551: INFO: Pod "azurefile-volume-tester-77g67": Phase="Running", Reason="", readiness=true. Elapsed: 14.27363902s
Apr 21 04:27:45.584: INFO: Pod "azurefile-volume-tester-77g67": Phase="Running", Reason="", readiness=true. Elapsed: 16.306811113s
Apr 21 04:27:47.617: INFO: Pod "azurefile-volume-tester-77g67": Phase="Running", Reason="", readiness=true. Elapsed: 18.339874907s
Apr 21 04:27:49.650: INFO: Pod "azurefile-volume-tester-77g67": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.37299929s
STEP: Saw pod success
Apr 21 04:27:49.650: INFO: Pod "azurefile-volume-tester-77g67" satisfied condition "Succeeded or Failed"
Apr 21 04:27:49.650: INFO: deleting Pod "azurefile-4801"/"azurefile-volume-tester-77g67"
Apr 21 04:27:49.692: INFO: Pod azurefile-volume-tester-77g67 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-77g67 in namespace azurefile-4801
Apr 21 04:27:49.732: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "azurefile-4801" for this suite.
... skipping 43 lines ...
======================================================================================
2022/04/21 04:27:50 Check successfully
Apr 21 04:27:50.891: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: creating secret smbcreds in namespace azurefile-1166
2022/04/21 04:27:50 run script: test/utils/get_smb_svc_public_ip.sh
2022/04/21 04:27:51 got output: 52.226.207.196
, error: <nil>
2022/04/21 04:27:51 use server on Windows: 52.226.207.196
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 21 04:27:51.181: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-rjh6m" in namespace "azurefile-1166" to be "Succeeded or Failed"
Apr 21 04:27:51.213: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 31.381225ms
Apr 21 04:27:53.247: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065074407s
Apr 21 04:27:55.282: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.100577102s
Apr 21 04:27:57.316: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.134681164s
Apr 21 04:27:59.350: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.168862474s
Apr 21 04:28:01.384: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 10.202208671s
Apr 21 04:28:03.419: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Pending", Reason="", readiness=false. Elapsed: 12.237339762s
Apr 21 04:28:05.453: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Running", Reason="", readiness=true. Elapsed: 14.27198264s
Apr 21 04:28:07.487: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Running", Reason="", readiness=true. Elapsed: 16.305854306s
Apr 21 04:28:09.521: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Running", Reason="", readiness=true. Elapsed: 18.339760092s
Apr 21 04:28:11.557: INFO: Pod "azurefile-volume-tester-rjh6m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.375346909s
STEP: Saw pod success
Apr 21 04:28:11.557: INFO: Pod "azurefile-volume-tester-rjh6m" satisfied condition "Succeeded or Failed"
Apr 21 04:28:11.557: INFO: deleting Pod "azurefile-1166"/"azurefile-volume-tester-rjh6m"
Apr 21 04:28:11.599: INFO: Pod azurefile-volume-tester-rjh6m has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-rjh6m in namespace azurefile-1166
Apr 21 04:28:11.643: INFO: deleting Secret smbcreds
Apr 21 04:28:11.676: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
... skipping 132 lines ...
Apr 21 04:28:35.112: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-wxkns] to have phase Bound
Apr 21 04:28:35.145: INFO: PersistentVolumeClaim pvc-wxkns found and phase=Bound (32.627416ms)
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 21 04:28:35.244: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l2rfx" in namespace "azurefile-5320" to be "Error status code"
Apr 21 04:28:35.276: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 31.405826ms
Apr 21 04:28:37.311: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066324146s
Apr 21 04:28:39.345: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.100263519s
Apr 21 04:28:41.380: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.135773666s
Apr 21 04:28:43.414: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.169632051s
Apr 21 04:28:45.449: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204053679s
Apr 21 04:28:47.485: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 12.240229313s
Apr 21 04:28:49.519: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Pending", Reason="", readiness=false. Elapsed: 14.274909744s
Apr 21 04:28:51.553: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Running", Reason="", readiness=true. Elapsed: 16.30810796s
Apr 21 04:28:53.588: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Running", Reason="", readiness=true. Elapsed: 18.343839209s
Apr 21 04:28:55.623: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Running", Reason="", readiness=true. Elapsed: 20.378525086s
Apr 21 04:28:57.658: INFO: Pod "azurefile-volume-tester-l2rfx": Phase="Failed", Reason="", readiness=false. Elapsed: 22.413711572s
STEP: Saw pod failure
Apr 21 04:28:57.658: INFO: Pod "azurefile-volume-tester-l2rfx" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 21 04:28:57.712: INFO: deleting Pod "azurefile-5320"/"azurefile-volume-tester-l2rfx"
Apr 21 04:28:57.757: INFO: Pod azurefile-volume-tester-l2rfx 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 55 lines ...
Apr 21 04:28:59.517: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-kdbzs] to have phase Bound
Apr 21 04:28:59.549: INFO: PersistentVolumeClaim pvc-kdbzs found and phase=Bound (31.631332ms)
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 21 04:28:59.645: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-thtp4" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 21 04:28:59.676: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 31.220566ms
Apr 21 04:29:01.710: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065039725s
Apr 21 04:29:03.744: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098994306s
Apr 21 04:29:05.778: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132645122s
Apr 21 04:29:07.812: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167201883s
Apr 21 04:29:09.847: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.201538446s
Apr 21 04:29:11.881: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Pending", Reason="", readiness=false. Elapsed: 12.23565094s
Apr 21 04:29:13.915: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Running", Reason="", readiness=true. Elapsed: 14.270207324s
Apr 21 04:29:15.951: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Running", Reason="", readiness=true. Elapsed: 16.305935467s
Apr 21 04:29:17.986: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Running", Reason="", readiness=true. Elapsed: 18.340485034s
Apr 21 04:29:20.019: INFO: Pod "azurefile-volume-tester-thtp4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.374119584s
STEP: Saw pod success
Apr 21 04:29:20.019: INFO: Pod "azurefile-volume-tester-thtp4" 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 21 04:29:20.092: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-g7lpv] to have phase Bound
Apr 21 04:29:20.127: INFO: PersistentVolumeClaim pvc-g7lpv found and phase=Bound (35.266944ms)
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 21 04:29:20.227: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-tdpwl" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 21 04:29:20.259: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Pending", Reason="", readiness=false. Elapsed: 31.746011ms
Apr 21 04:29:22.294: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066703433s
Apr 21 04:29:24.329: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.102656642s
Apr 21 04:29:26.365: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.138268915s
Apr 21 04:29:28.400: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.173250316s
Apr 21 04:29:30.434: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Pending", Reason="", readiness=false. Elapsed: 10.207385732s
Apr 21 04:29:32.469: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Running", Reason="", readiness=true. Elapsed: 12.241995726s
Apr 21 04:29:34.504: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Running", Reason="", readiness=true. Elapsed: 14.276794118s
Apr 21 04:29:36.537: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Running", Reason="", readiness=true. Elapsed: 16.310469849s
Apr 21 04:29:38.571: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Running", Reason="", readiness=true. Elapsed: 18.344454831s
Apr 21 04:29:40.605: INFO: Pod "azurefile-volume-tester-tdpwl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.378490996s
STEP: Saw pod success
Apr 21 04:29:40.605: INFO: Pod "azurefile-volume-tester-tdpwl" 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 21 04:29:40.676: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-qs4cz] to have phase Bound
Apr 21 04:29:40.708: INFO: PersistentVolumeClaim pvc-qs4cz found and phase=Bound (31.317972ms)
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 21 04:29:40.814: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-nprwh" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 21 04:29:40.858: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Pending", Reason="", readiness=false. Elapsed: 43.662283ms
Apr 21 04:29:42.891: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076634089s
Apr 21 04:29:44.925: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.110377327s
Apr 21 04:29:46.958: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.143927635s
Apr 21 04:29:48.992: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.177270101s
Apr 21 04:29:51.025: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210891438s
Apr 21 04:29:53.061: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Running", Reason="", readiness=true. Elapsed: 12.247047532s
Apr 21 04:29:55.095: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Running", Reason="", readiness=true. Elapsed: 14.281003842s
Apr 21 04:29:57.130: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Running", Reason="", readiness=true. Elapsed: 16.315292658s
Apr 21 04:29:59.165: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Running", Reason="", readiness=true. Elapsed: 18.350203208s
Apr 21 04:30:01.199: INFO: Pod "azurefile-volume-tester-nprwh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.384477851s
STEP: Saw pod success
Apr 21 04:30:01.199: INFO: Pod "azurefile-volume-tester-nprwh" 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 21 04:30:01.270: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-bznl5] to have phase Bound
Apr 21 04:30:01.301: INFO: PersistentVolumeClaim pvc-bznl5 found and phase=Bound (31.433184ms)
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 21 04:30:01.399: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-d6f5l" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 21 04:30:01.431: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Pending", Reason="", readiness=false. Elapsed: 31.78798ms
Apr 21 04:30:03.466: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066990266s
Apr 21 04:30:05.501: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Pending", Reason="", readiness=false. Elapsed: 4.101267112s
Apr 21 04:30:07.534: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Pending", Reason="", readiness=false. Elapsed: 6.13490346s
Apr 21 04:30:09.567: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Pending", Reason="", readiness=false. Elapsed: 8.168057461s
Apr 21 04:30:11.601: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Pending", Reason="", readiness=false. Elapsed: 10.201177057s
Apr 21 04:30:13.633: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Running", Reason="", readiness=true. Elapsed: 12.234125389s
Apr 21 04:30:15.667: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Running", Reason="", readiness=true. Elapsed: 14.267976375s
Apr 21 04:30:17.704: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Running", Reason="", readiness=true. Elapsed: 16.304489395s
Apr 21 04:30:19.738: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Running", Reason="", readiness=true. Elapsed: 18.338441689s
Apr 21 04:30:21.775: INFO: Pod "azurefile-volume-tester-d6f5l": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.37595515s
STEP: Saw pod success
Apr 21 04:30:21.775: INFO: Pod "azurefile-volume-tester-d6f5l" 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 21 04:30:21.852: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-s69wc] to have phase Bound
Apr 21 04:30:21.895: INFO: PersistentVolumeClaim pvc-s69wc found but phase is Pending instead of Bound.
Apr 21 04:30:23.928: INFO: PersistentVolumeClaim pvc-s69wc found and phase=Bound (2.076064405s)
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 21 04:30:24.027: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-sx2mw" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 21 04:30:24.064: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Pending", Reason="", readiness=false. Elapsed: 37.007961ms
Apr 21 04:30:26.098: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.071382616s
Apr 21 04:30:28.132: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.104587051s
Apr 21 04:30:30.165: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.13797623s
Apr 21 04:30:32.200: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.173359844s
Apr 21 04:30:34.235: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.207896322s
Apr 21 04:30:36.271: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Running", Reason="", readiness=true. Elapsed: 12.243811857s
Apr 21 04:30:38.305: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Running", Reason="", readiness=true. Elapsed: 14.27760719s
Apr 21 04:30:40.339: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Running", Reason="", readiness=true. Elapsed: 16.312315099s
Apr 21 04:30:42.373: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Running", Reason="", readiness=true. Elapsed: 18.345996539s
Apr 21 04:30:44.407: INFO: Pod "azurefile-volume-tester-sx2mw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.380135275s
STEP: Saw pod success
Apr 21 04:30:44.407: INFO: Pod "azurefile-volume-tester-sx2mw" 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 21 04:30:44.474: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-djfpg] to have phase Bound
Apr 21 04:30:44.506: INFO: PersistentVolumeClaim pvc-djfpg found and phase=Bound (31.653479ms)
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 21 04:30:44.603: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vbmjl" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 21 04:30:44.638: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Pending", Reason="", readiness=false. Elapsed: 34.713539ms
Apr 21 04:30:46.670: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066946539s
Apr 21 04:30:48.704: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.101032201s
Apr 21 04:30:50.738: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.135198008s
Apr 21 04:30:52.772: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.169201279s
Apr 21 04:30:54.808: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20471205s
Apr 21 04:30:56.842: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Running", Reason="", readiness=true. Elapsed: 12.238897629s
Apr 21 04:30:58.877: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Running", Reason="", readiness=true. Elapsed: 14.273931719s
Apr 21 04:31:00.911: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Running", Reason="", readiness=true. Elapsed: 16.30763002s
Apr 21 04:31:02.945: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Running", Reason="", readiness=true. Elapsed: 18.342182612s
Apr 21 04:31:04.979: INFO: Pod "azurefile-volume-tester-vbmjl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.375796333s
STEP: Saw pod success
Apr 21 04:31:04.979: INFO: Pod "azurefile-volume-tester-vbmjl" satisfied condition "Succeeded or Failed"
Apr 21 04:31:04.979: INFO: deleting Pod "azurefile-9103"/"azurefile-volume-tester-vbmjl"
Apr 21 04:31:05.044: INFO: Pod azurefile-volume-tester-vbmjl has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-vbmjl in namespace azurefile-9103
Apr 21 04:31:05.085: INFO: deleting PVC "azurefile-9103"/"pvc-djfpg"
Apr 21 04:31:05.085: INFO: Deleting PersistentVolumeClaim "pvc-djfpg"
... skipping 143 lines ...
Apr 21 04:31:09.978: INFO: PersistentVolumeClaim pvc-zhx6j found but phase is Pending instead of Bound.
Apr 21 04:31:12.011: INFO: PersistentVolumeClaim pvc-zhx6j found and phase=Bound (2.065190151s)
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 21 04:31:12.110: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-v6ptr" in namespace "azurefile-8470" to be "Succeeded or Failed"
Apr 21 04:31:12.142: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 32.248046ms
Apr 21 04:31:14.175: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065862158s
Apr 21 04:31:16.208: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098791835s
Apr 21 04:31:18.243: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133073784s
Apr 21 04:31:20.277: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167271035s
Apr 21 04:31:22.311: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.201037501s
Apr 21 04:31:24.345: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Pending", Reason="", readiness=false. Elapsed: 12.235483425s
Apr 21 04:31:26.379: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Running", Reason="", readiness=true. Elapsed: 14.269833866s
Apr 21 04:31:28.413: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Running", Reason="", readiness=true. Elapsed: 16.303853386s
Apr 21 04:31:30.449: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Running", Reason="", readiness=true. Elapsed: 18.339029376s
Apr 21 04:31:32.483: INFO: Pod "azurefile-volume-tester-v6ptr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.373115223s
STEP: Saw pod success
Apr 21 04:31:32.483: INFO: Pod "azurefile-volume-tester-v6ptr" satisfied condition "Succeeded or Failed"
Apr 21 04:31:32.483: INFO: deleting Pod "azurefile-8470"/"azurefile-volume-tester-v6ptr"
Apr 21 04:31:32.526: INFO: Pod azurefile-volume-tester-v6ptr has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-v6ptr in namespace azurefile-8470
Apr 21 04:31:32.568: INFO: deleting PVC "azurefile-8470"/"pvc-zhx6j"
Apr 21 04:31:32.568: INFO: Deleting PersistentVolumeClaim "pvc-zhx6j"
... skipping 33 lines ...
Apr 21 04:31:34.159: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-wtpj5] to have phase Bound
Apr 21 04:31:34.191: INFO: PersistentVolumeClaim pvc-wtpj5 found and phase=Bound (31.501317ms)
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 21 04:31:34.294: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8frb6" in namespace "azurefile-7029" to be "Succeeded or Failed"
Apr 21 04:31:34.325: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Pending", Reason="", readiness=false. Elapsed: 31.486378ms
Apr 21 04:31:36.359: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064689716s
Apr 21 04:31:38.392: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.097551956s
Apr 21 04:31:40.424: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.129789084s
Apr 21 04:31:42.458: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.163660265s
Apr 21 04:31:44.492: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Pending", Reason="", readiness=false. Elapsed: 10.197826481s
... skipping 2 lines ...
Apr 21 04:31:50.596: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Running", Reason="", readiness=true. Elapsed: 16.301669721s
Apr 21 04:31:52.630: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Running", Reason="", readiness=true. Elapsed: 18.335770194s
Apr 21 04:31:54.663: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Running", Reason="", readiness=true. Elapsed: 20.368737162s
Apr 21 04:31:56.697: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Running", Reason="", readiness=true. Elapsed: 22.402921444s
Apr 21 04:31:58.730: INFO: Pod "azurefile-volume-tester-8frb6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 24.436385868s
STEP: Saw pod success
Apr 21 04:31:58.730: INFO: Pod "azurefile-volume-tester-8frb6" satisfied condition "Succeeded or Failed"
Apr 21 04:31:58.730: INFO: deleting Pod "azurefile-7029"/"azurefile-volume-tester-8frb6"
Apr 21 04:31:58.775: INFO: Pod azurefile-volume-tester-8frb6 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-8frb6 in namespace azurefile-7029
Apr 21 04:31:58.831: INFO: deleting PVC "azurefile-7029"/"pvc-wtpj5"
Apr 21 04:31:58.831: INFO: Deleting PersistentVolumeClaim "pvc-wtpj5"
... skipping 86 lines ...
Platform: linux/amd64

Streaming logs below:
I0421 04:06:49.285381       1 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-6a13648397110ae4586db2ee2bd9457c1a00fa53 gc/go1.18.1 (amd64-linux) e2e-test
I0421 04:06:49.285780       1 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0421 04:06:49.300117       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 14 milliseconds
W0421 04:06:49.300391       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
I0421 04:06:49.300421       1 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0421 04:06:49.300433       1 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0421 04:06:49.300473       1 azure.go:101] read cloud config from file: /etc/kubernetes/azure.json successfully
I0421 04:06:49.301946       1 azure_auth.go:245] Using AzurePublicCloud environment
I0421 04:06:49.302013       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0421 04:06:49.302110       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 2918 lines ...
Platform: windows/amd64

Streaming logs below:
I0421 04:10:47.805065    6740 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-6a13648397110ae4586db2ee2bd9457c1a00fa53 gc/go1.18.1 (amd64-windows) e2e-test
I0421 04:10:47.820330    6740 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0421 04:10:47.870787    6740 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 39 milliseconds
W0421 04:10:47.875474    6740 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
I0421 04:10:47.875546    6740 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0421 04:10:47.875938    6740 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0421 04:10:47.876019    6740 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0421 04:10:47.878496    6740 azure_auth.go:245] Using AzurePublicCloud environment
I0421 04:10:47.878916    6740 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0421 04:10:47.883299    6740 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 1272 lines ...
I0421 04:27:29.539856    6740 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0421 04:27:29.539856    6740 utils.go:77] GRPC request: {}
I0421 04:27:29.541316    6740 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0421 04:27:29.548207    6740 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0421 04:27:29.548207    6740 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\ba42c385-94ba-47b6-9e55-63ea92da3659\\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-77g67","csi.storage.k8s.io/pod.namespace":"azurefile-4801","csi.storage.k8s.io/pod.uid":"ba42c385-94ba-47b6-9e55-63ea92da3659","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"azure-storage-account-fe0adf6af95b24b319cea4d-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-bb6a97ac1b167527f2d20bc2b066b990f3207c02bd60f1e22de65f900247d08a"}
I0421 04:27:29.548207    6740 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-bb6a97ac1b167527f2d20bc2b066b990f3207c02bd60f1e22de65f900247d08a) mount on c:\var\lib\kubelet\pods\ba42c385-94ba-47b6-9e55-63ea92da3659\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-77g67 csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:ba42c385-94ba-47b6-9e55-63ea92da3659 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-fe0adf6af95b24b319cea4d-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]
W0421 04:27:29.548207    6740 azurefile.go:546] parsing volumeID(csi-bb6a97ac1b167527f2d20bc2b066b990f3207c02bd60f1e22de65f900247d08a) return with error: error parsing volume id: "csi-bb6a97ac1b167527f2d20bc2b066b990f3207c02bd60f1e22de65f900247d08a", should at least contain two #
I0421 04:27:29.559195    6740 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-4801/secrets/azure-storage-account-fe0adf6af95b24b319cea4d-secret 200 OK in 8 milliseconds
I0421 04:27:29.562600    6740 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\ba42c385-94ba-47b6-9e55-63ea92da3659\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-bb6a97ac1b167527f2d20bc2b066b990f3207c02bd60f1e22de65f900247d08a) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-77g67 csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:ba42c385-94ba-47b6-9e55-63ea92da3659 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-fe0adf6af95b24b319cea4d-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\fe0adf6af95b24b319cea4d]) volumeMountGroup()
I0421 04:27:29.562600    6740 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\ba42c385-94ba-47b6-9e55-63ea92da3659\volumes\kubernetes.io~csi\test-volume-1\mount
I0421 04:27:29.562600    6740 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\ba42c385-94ba-47b6-9e55-63ea92da3659\volumes\kubernetes.io~csi\test-volume-1\mount
I0421 04:27:29.564234    6740 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\ba42c385-94ba-47b6-9e55-63ea92da3659\volumes\kubernetes.io~csi\test-volume-1\mount
I0421 04:27:29.564909    6740 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\ba42c385-94ba-47b6-9e55-63ea92da3659\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 39 lines ...
I0421 04:27:51.295386    6740 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0421 04:27:51.295386    6740 utils.go:77] GRPC request: {}
I0421 04:27:51.295386    6740 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0421 04:27:51.298263    6740 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0421 04:27:51.298303    6740 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\ca8e0740-351c-4819-9e00-d736fc5c97a6\\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-rjh6m","csi.storage.k8s.io/pod.namespace":"azurefile-1166","csi.storage.k8s.io/pod.uid":"ca8e0740-351c-4819-9e00-d736fc5c97a6","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"smbcreds","server":"52.226.207.196","shareName":"share"},"volume_id":"csi-eb5ab26c4036386d8e5303a197634b131d24a26442f3d0d7a0a63d33c9e7eec3"}
I0421 04:27:51.298560    6740 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-eb5ab26c4036386d8e5303a197634b131d24a26442f3d0d7a0a63d33c9e7eec3) mount on c:\var\lib\kubelet\pods\ca8e0740-351c-4819-9e00-d736fc5c97a6\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-rjh6m csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:ca8e0740-351c-4819-9e00-d736fc5c97a6 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:52.226.207.196 shareName:share storageaccount:]
W0421 04:27:51.298665    6740 azurefile.go:546] parsing volumeID(csi-eb5ab26c4036386d8e5303a197634b131d24a26442f3d0d7a0a63d33c9e7eec3) return with error: error parsing volume id: "csi-eb5ab26c4036386d8e5303a197634b131d24a26442f3d0d7a0a63d33c9e7eec3", should at least contain two #
I0421 04:27:51.302261    6740 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-1166/secrets/smbcreds 200 OK in 3 milliseconds
I0421 04:27:51.302868    6740 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\ca8e0740-351c-4819-9e00-d736fc5c97a6\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-eb5ab26c4036386d8e5303a197634b131d24a26442f3d0d7a0a63d33c9e7eec3) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-rjh6m csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:ca8e0740-351c-4819-9e00-d736fc5c97a6 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:52.226.207.196 shareName:share storageaccount:]) mountflags([]) mountOptions([AZURE\USERNAME]) volumeMountGroup()
I0421 04:27:51.302939    6740 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\ca8e0740-351c-4819-9e00-d736fc5c97a6\volumes\kubernetes.io~csi\test-volume-1\mount
I0421 04:27:51.302967    6740 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\ca8e0740-351c-4819-9e00-d736fc5c97a6\volumes\kubernetes.io~csi\test-volume-1\mount
I0421 04:27:51.304472    6740 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\ca8e0740-351c-4819-9e00-d736fc5c97a6\volumes\kubernetes.io~csi\test-volume-1\mount
I0421 04:27:51.305084    6740 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\ca8e0740-351c-4819-9e00-d736fc5c97a6\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 26 lines ...
I0421 04:28:35.557184    6740 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0421 04:28:35.557184    6740 utils.go:77] GRPC request: {}
I0421 04:28:35.557184    6740 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0421 04:28:35.558468    6740 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume
I0421 04:28:35.558468    6740 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-5320-file.csi.azure.com-preprovsioned-pv-9wzg2\\globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_id":"capz-wu3n7j#f62084dbabd054de985d3f4#pre-provisioned-readonly##pre-provisioned-readonly"}
I0421 04:28:35.563482    6740 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/default/secrets/azure-storage-account-f62084dbabd054de985d3f4-secret 404 Not Found in 2 milliseconds
I0421 04:28:35.563651    6740 azurefile.go:616] could not get account(f62084dbabd054de985d3f4) key from secret(azure-storage-account-f62084dbabd054de985d3f4-secret), error: could not get secret(azure-storage-account-f62084dbabd054de985d3f4-secret): secrets "azure-storage-account-f62084dbabd054de985d3f4-secret" not found, use cluster identity to get account key instead
(2022-04-21T04:28:35.5702371Z) INFO: REQUEST: POST https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token
Content-Type: application/x-www-form-urlencoded
User-Agent: Go/go1.18.1 (amd64-windows) go-autorest/adal/v1.0.0
(2022-04-21T04:28:35.8858617Z) INFO: RESPONSE: 200 https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token
Content-Type: application/json; charset=utf-8
P3p: CP="DSP CUR OTPi IND OTRi ONL FIN"
... skipping 134 lines ...
I0421 04:29:03.054070    6740 utils.go:77] GRPC request: {}
I0421 04:29:03.054139    6740 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0421 04:29:03.055881    6740 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0421 04:29:03.055881    6740 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\\globalmount","target_path":"c:\\var\\lib\\kubelet\\pods\\7541b52f-f3e6-4447-b828-3495f17a069d\\volumes\\kubernetes.io~csi\\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\\mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"azurefile-volume-tester-thtp4","csi.storage.k8s.io/pod.namespace":"azurefile-9103","csi.storage.k8s.io/pod.uid":"7541b52f-f3e6-4447-b828-3495f17a069d","csi.storage.k8s.io/serviceAccount.name":"default"},"volume_id":"capz-wu3n7j#f62084dbabd054de985d3f4#pre-provisioned-multiple-pods##pre-provisioned-multiple-pods1"}
I0421 04:29:03.056455    6740 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount
I0421 04:29:03.056455    6740 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount
W0421 04:29:03.145062    6740 nodeserver.go:489] ReadDir c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount failed with open c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount: Access is denied., unmount this directory
I0421 04:29:03.145787    6740 safe_mounter_windows.go:147] Unmount: c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount
I0421 04:29:03.145787    6740 safe_mounter_windows.go:133] Remove directory: c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount
E0421 04:29:03.149171    6740 utils.go:81] GRPC error: rpc error: code = Internal desc = Could not mount target "c:\\var\\lib\\kubelet\\pods\\7541b52f-f3e6-4447-b828-3495f17a069d\\volumes\\kubernetes.io~csi\\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\\mount": open c:\var\lib\kubelet\pods\7541b52f-f3e6-4447-b828-3495f17a069d\volumes\kubernetes.io~csi\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\mount: Access is denied.
I0421 04:29:16.349332    6740 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0421 04:29:16.349371    6740 utils.go:77] GRPC request: {}
I0421 04:29:16.349371    6740 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0421 04:29:16.350495    6740 utils.go:76] GRPC call: /csi.v1.Node/NodeGetVolumeStats
I0421 04:29:16.350495    6740 utils.go:77] GRPC request: {"volume_id":"capz-wu3n7j#f62084dbabd054de985d3f4#pre-provisioned-multiple-pods##pre-provisioned-multiple-pods1","volume_path":"c:\\var\\lib\\kubelet\\pods\\7541b52f-f3e6-4447-b828-3495f17a069d\\volumes\\kubernetes.io~csi\\azurefile-9103-file.csi.azure.com-preprovsioned-pv-8276d\\mount"}
I0421 04:29:16.351439    6740 utils.go:83] GRPC response: {"usage":[{"available":117435953152,"total":136912564224,"unit":1,"used":19476611072},{"unit":2}]}
... skipping 578 lines ...
Platform: windows/amd64

Streaming logs below:
I0421 04:07:47.596997    6860 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-6a13648397110ae4586db2ee2bd9457c1a00fa53 gc/go1.18.1 (amd64-windows) e2e-test
I0421 04:07:47.612692    6860 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0421 04:07:47.640073    6860 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 22 milliseconds
W0421 04:07:47.645643    6860 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
I0421 04:07:47.645643    6860 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0421 04:07:47.645643    6860 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0421 04:07:47.646366    6860 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0421 04:07:47.648285    6860 azure_auth.go:245] Using AzurePublicCloud environment
I0421 04:07:47.648886    6860 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0421 04:07:47.653150    6860 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 595 lines ...

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


Summarizing 1 Failure:

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

Ran 20 of 34 Specs in 1597.202 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 (1597.21s)
FAIL
FAIL	sigs.k8s.io/azurefile-csi-driver/test/e2e	1597.302s
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 81 lines ...
daemonset.apps "log-dump-node-windows" deleted
================ REDACTING LOGS ================
All sensitive variables are redacted
cluster.cluster.x-k8s.io "capz-wu3n7j" deleted
kind delete cluster --name=capz || true
Deleting cluster "capz" ...
ERROR: failed to delete cluster "capz": failed to delete nodes: command "docker rm -f -v capz-control-plane" failed with error: exit status 1

Command Output: Error response from daemon: Could not kill running container 4a0e877b6678473f5f9e33ccf48ec0e77230350440235f6f7e7d67870ee8e2f2, cannot remove - tried to kill container, but did not receive an exit event
kind delete cluster --name=capz-e2e || true
Deleting cluster "capz-e2e" ...
+ EXIT_VALUE=2
+ set +o xtrace
Cleaning up after docker in docker.
================================================================================
Cleaning up after docker
533e7efca983
Error response from daemon: Could not kill running container 4a0e877b6678473f5f9e33ccf48ec0e77230350440235f6f7e7d67870ee8e2f2, cannot remove - tried to kill container, but did not receive an exit event
Stopping Docker: dockerProgram process in pidfile '/var/run/docker-ssd.pid', 1 process(es), refused to die.
================================================================================
Done cleaning up after docker in docker.