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 02:31
Elapsed47m22s
Revision59749427e6f8cf35a4eb23553e9a03ca204807b5
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] 9m45s

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 | 0xc000875a60>: {
        s: "pod \"azurefile-volume-tester-msl7v\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +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-18 02:49:44 +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-18 02:49:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.6 PodIP:192.168.46.132 PodIPs:[{IP:192.168.46.132}] StartTime:2022-04-18 02:49:44 +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://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597 Started:0xc00073e568}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
    }
    pod "azurefile-volume-tester-msl7v" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +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-18 02:49:44 +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-18 02:49:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.6 PodIP:192.168.46.132 PodIPs:[{IP:192.168.46.132}] StartTime:2022-04-18 02:49:44 +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://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597 Started:0xc00073e568}] 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-msl7v mentions in log files | View test history on testgrid

Show 19 Passed Tests
Show 14 Skipped Tests

Error lines from build-log.txt

... skipping 670 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 1169 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 02:47:40.898158   36669 azure.go:78] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
I0418 02:47:40.899319   36669 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0418 02:47:40.899346   36669 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0418 02:47:40.899357   36669 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0418 02:47:40.899364   36669 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0418 02:47:40.899370   36669 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
I0418 02:47:40.899378   36669 driver.go:112] Enabling volume access mode: SINGLE_NODE_WRITER
... skipping 117 lines ...
Apr 18 02:49:42.027: INFO: PersistentVolumeClaim pvc-hhzmx found but phase is Pending instead of Bound.
Apr 18 02:49:44.130: INFO: PersistentVolumeClaim pvc-hhzmx found and phase=Bound (1m36.862074268s)
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 02:49:44.440: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-msl7v" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 02:49:44.542: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 101.919457ms
Apr 18 02:49:46.644: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20463861s
Apr 18 02:49:48.748: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 4.308091955s
Apr 18 02:49:50.851: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 6.410968301s
Apr 18 02:49:52.954: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 8.514242289s
Apr 18 02:49:55.058: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 10.618146635s
... skipping 214 lines ...
Apr 18 02:57:27.987: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m43.547263354s
Apr 18 02:57:30.093: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m45.653251601s
Apr 18 02:57:32.201: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m47.760990006s
Apr 18 02:57:34.330: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m49.890595986s
Apr 18 02:57:36.437: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m51.997492219s
Apr 18 02:57:38.544: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Pending", Reason="", readiness=false. Elapsed: 7m54.103835152s
Apr 18 02:57:40.649: INFO: Pod "azurefile-volume-tester-msl7v": Phase="Failed", Reason="", readiness=false. Elapsed: 7m56.209396611s
Apr 18 02:57:40.650: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-msl7v"
Apr 18 02:57:40.768: INFO: Pod azurefile-volume-tester-msl7v has the following logs: 
STEP: Deleting pod azurefile-volume-tester-msl7v in namespace azurefile-2540
Apr 18 02:57:40.881: INFO: deleting PVC "azurefile-2540"/"pvc-hhzmx"
Apr 18 02:57:40.881: INFO: Deleting PersistentVolumeClaim "pvc-hhzmx"
STEP: waiting for claim's PV "pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" to be deleted
... skipping 6 lines ...
STEP: Collecting events from namespace "azurefile-2540".
STEP: Found 12 events.
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:48:07 +0000 UTC - event for pvc-hhzmx: {file.csi.azure.com_capz-wzptwz-md-0-qhbgq_cac1fefa-9ae1-408c-980f-4471ce6013ec } Provisioning: External provisioner is provisioning volume for claim "azurefile-2540/pvc-hhzmx"
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:48:07 +0000 UTC - event for pvc-hhzmx: {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 18 02:57:46.726: INFO: At 2022-04-18 02:49:43 +0000 UTC - event for pvc-hhzmx: {file.csi.azure.com_capz-wzptwz-md-0-qhbgq_cac1fefa-9ae1-408c-980f-4471ce6013ec } ProvisioningSucceeded: Successfully provisioned volume pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:49:44 +0000 UTC - event for azurefile-volume-tester-msl7v: {default-scheduler } Scheduled: Successfully assigned azurefile-2540/azurefile-volume-tester-msl7v to capz-wzpt-d5cvj
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:49:50 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} FailedMount: MountVolume.MountDevice failed for volume "pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" : rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:51:14 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:55:40 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m25.2310247s
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:55:40 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Created: Created container volume-tester
Apr 18 02:57:46.726: INFO: At 2022-04-18 02:57:40 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 18 02:57:46.727: INFO: At 2022-04-18 02:57:40 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Failed: Error: context deadline exceeded
Apr 18 02:57:46.727: INFO: At 2022-04-18 02:57:44 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Started: Started container volume-tester
Apr 18 02:57:46.727: INFO: At 2022-04-18 02:57:45 +0000 UTC - event for azurefile-volume-tester-msl7v: {kubelet capz-wzpt-d5cvj} Killing: Stopping container volume-tester
Apr 18 02:57:46.829: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 02:57:46.829: INFO: 
Apr 18 02:57:46.971: INFO: 
Logging node info for node capz-wzpt-4rt6n
... skipping 114 lines ...
• Failure [585.741 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 | 0xc000875a60>: {
          s: "pod \"azurefile-volume-tester-msl7v\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +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-18 02:49:44 +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-18 02:49:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.6 PodIP:192.168.46.132 PodIPs:[{IP:192.168.46.132}] StartTime:2022-04-18 02:49:44 +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://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597 Started:0xc00073e568}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
      }
      pod "azurefile-volume-tester-msl7v" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 02:49:44 +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-18 02:49:44 +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-18 02:49:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.6 PodIP:192.168.46.132 PodIPs:[{IP:192.168.46.132}] StartTime:2022-04-18 02:49:44 +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://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://9de25405394592c272c9f714b942004508380094a558e553638ec5dcc15cf597 Started:0xc00073e568}] 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 18 02:58:12.571: INFO: PersistentVolumeClaim pvc-hzxpm found but phase is Pending instead of Bound.
Apr 18 02:58:14.673: INFO: PersistentVolumeClaim pvc-hzxpm found and phase=Bound (21.138167901s)
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 02:58:14.983: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dcpjk" in namespace "azurefile-4728" to be "Succeeded or Failed"
Apr 18 02:58:15.085: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 101.687142ms
Apr 18 02:58:17.189: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205679516s
Apr 18 02:58:19.294: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.310950302s
Apr 18 02:58:21.400: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.416433971s
Apr 18 02:58:23.505: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522097345s
Apr 18 02:58:25.611: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.62806856s
Apr 18 02:58:27.718: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 12.735239491s
Apr 18 02:58:29.825: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Pending", Reason="", readiness=false. Elapsed: 14.841593806s
Apr 18 02:58:31.931: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Running", Reason="", readiness=true. Elapsed: 16.947289302s
Apr 18 02:58:34.037: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Running", Reason="", readiness=true. Elapsed: 19.053642105s
Apr 18 02:58:36.143: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Running", Reason="", readiness=true. Elapsed: 21.159781331s
Apr 18 02:58:38.249: INFO: Pod "azurefile-volume-tester-dcpjk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 23.266016527s
STEP: Saw pod success
Apr 18 02:58:38.249: INFO: Pod "azurefile-volume-tester-dcpjk" satisfied condition "Succeeded or Failed"
Apr 18 02:58:38.249: INFO: deleting Pod "azurefile-4728"/"azurefile-volume-tester-dcpjk"
Apr 18 02:58:38.362: INFO: Pod azurefile-volume-tester-dcpjk has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-dcpjk in namespace azurefile-4728
Apr 18 02:58:38.472: INFO: deleting PVC "azurefile-4728"/"pvc-hzxpm"
Apr 18 02:58:38.472: INFO: Deleting PersistentVolumeClaim "pvc-hzxpm"
... skipping 115 lines ...
Apr 18 02:59:43.402: INFO: PersistentVolumeClaim pvc-6gk6w found but phase is Pending instead of Bound.
Apr 18 02:59:45.506: INFO: PersistentVolumeClaim pvc-6gk6w found and phase=Bound (21.133516188s)
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 02:59:45.816: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-xjzdt" in namespace "azurefile-2790" to be "Error status code"
Apr 18 02:59:45.922: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Pending", Reason="", readiness=false. Elapsed: 106.059912ms
Apr 18 02:59:48.025: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209264684s
Apr 18 02:59:50.131: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.314865331s
Apr 18 02:59:52.237: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.420863526s
Apr 18 02:59:54.344: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.527801852s
Apr 18 02:59:56.450: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.63374959s
Apr 18 02:59:58.556: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Running", Reason="", readiness=true. Elapsed: 12.740017483s
Apr 18 03:00:00.663: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Running", Reason="", readiness=true. Elapsed: 14.846519612s
Apr 18 03:00:02.768: INFO: Pod "azurefile-volume-tester-xjzdt": Phase="Failed", Reason="", readiness=false. Elapsed: 16.951961742s
STEP: Saw pod failure
Apr 18 03:00:02.768: INFO: Pod "azurefile-volume-tester-xjzdt" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 03:00:02.883: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-xjzdt"
Apr 18 03:00:02.989: INFO: Pod azurefile-volume-tester-xjzdt 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 204 lines ...
Apr 18 03:01:20.334: INFO: PersistentVolumeClaim pvc-dgnrw found but phase is Pending instead of Bound.
Apr 18 03:01:22.437: INFO: PersistentVolumeClaim pvc-dgnrw found and phase=Bound (2.205066078s)
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 03:01:22.745: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-n2zxp" in namespace "azurefile-4538" to be "Succeeded or Failed"
Apr 18 03:01:22.846: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Pending", Reason="", readiness=false. Elapsed: 101.377452ms
Apr 18 03:01:24.949: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20462077s
Apr 18 03:01:27.055: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Pending", Reason="", readiness=false. Elapsed: 4.310161553s
Apr 18 03:01:29.160: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Pending", Reason="", readiness=false. Elapsed: 6.415448922s
Apr 18 03:01:31.265: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Pending", Reason="", readiness=false. Elapsed: 8.520779391s
Apr 18 03:01:33.371: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Pending", Reason="", readiness=false. Elapsed: 10.626294392s
Apr 18 03:01:35.479: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Running", Reason="", readiness=true. Elapsed: 12.734797854s
Apr 18 03:01:37.586: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Running", Reason="", readiness=true. Elapsed: 14.841138742s
Apr 18 03:01:39.691: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Running", Reason="", readiness=true. Elapsed: 16.946223199s
Apr 18 03:01:41.796: INFO: Pod "azurefile-volume-tester-n2zxp": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.050918935s
STEP: Saw pod success
Apr 18 03:01:41.796: INFO: Pod "azurefile-volume-tester-n2zxp" 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 03:02:12.483: INFO: deleting Pod "azurefile-4538"/"azurefile-volume-tester-n2zxp"
... skipping 302 lines ...
Apr 18 03:02:41.174: INFO: PersistentVolumeClaim pvc-jt4ck found but phase is Pending instead of Bound.
Apr 18 03:02:43.278: INFO: PersistentVolumeClaim pvc-jt4ck found and phase=Bound (2.205549059s)
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 03:02:43.586: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8xkdr" in namespace "azurefile-7726" to be "Succeeded or Failed"
Apr 18 03:02:43.691: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 104.504908ms
Apr 18 03:02:45.797: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210907766s
Apr 18 03:02:47.904: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.318191913s
Apr 18 03:02:50.010: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.423545936s
Apr 18 03:02:52.116: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.529340413s
Apr 18 03:02:54.222: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.635872634s
Apr 18 03:02:56.328: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 12.741429486s
Apr 18 03:02:58.435: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Pending", Reason="", readiness=false. Elapsed: 14.848577785s
Apr 18 03:03:00.541: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Running", Reason="", readiness=true. Elapsed: 16.954621892s
Apr 18 03:03:02.647: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Running", Reason="", readiness=true. Elapsed: 19.060381254s
Apr 18 03:03:04.752: INFO: Pod "azurefile-volume-tester-8xkdr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 21.165277202s
STEP: Saw pod success
Apr 18 03:03:04.752: INFO: Pod "azurefile-volume-tester-8xkdr" satisfied condition "Succeeded or Failed"
Apr 18 03:03:04.752: INFO: deleting Pod "azurefile-7726"/"azurefile-volume-tester-8xkdr"
Apr 18 03:03:05.242: INFO: Pod azurefile-volume-tester-8xkdr has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-8xkdr in namespace azurefile-7726
Apr 18 03:03:05.363: INFO: deleting PVC "azurefile-7726"/"pvc-jt4ck"
Apr 18 03:03:05.363: INFO: Deleting PersistentVolumeClaim "pvc-jt4ck"
... skipping 90 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 03:03:12 Check successfully
Apr 18 03:03:12.249: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 03:03:12 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 03:03:12 got output: azure-storage-account-f44e0972f9efd4c459bc1ac-secret
, error: <nil>
2022/04/18 03:03:12 got storage account secret name: azure-storage-account-f44e0972f9efd4c459bc1ac-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 03:03:12.874: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-7mvw4] to have phase Bound
Apr 18 03:03:12.976: INFO: PersistentVolumeClaim pvc-7mvw4 found but phase is Pending instead of Bound.
Apr 18 03:03:15.080: INFO: PersistentVolumeClaim pvc-7mvw4 found and phase=Bound (2.205747161s)
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 03:03:15.387: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lvdnj" in namespace "azurefile-1387" to be "Succeeded or Failed"
Apr 18 03:03:15.489: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Pending", Reason="", readiness=false. Elapsed: 101.898392ms
Apr 18 03:03:17.591: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204077068s
Apr 18 03:03:19.696: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309290799s
Apr 18 03:03:21.801: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.414855245s
Apr 18 03:03:23.907: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.520187834s
Apr 18 03:03:26.013: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.626203967s
Apr 18 03:03:28.119: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Running", Reason="", readiness=true. Elapsed: 12.732835313s
Apr 18 03:03:30.226: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Running", Reason="", readiness=true. Elapsed: 14.839233895s
Apr 18 03:03:32.331: INFO: Pod "azurefile-volume-tester-lvdnj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.944570059s
STEP: Saw pod success
Apr 18 03:03:32.331: INFO: Pod "azurefile-volume-tester-lvdnj" satisfied condition "Succeeded or Failed"
Apr 18 03:03:32.331: INFO: deleting Pod "azurefile-1387"/"azurefile-volume-tester-lvdnj"
Apr 18 03:03:32.443: INFO: Pod azurefile-volume-tester-lvdnj has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-lvdnj in namespace azurefile-1387
Apr 18 03:03:32.564: INFO: deleting PVC "azurefile-1387"/"pvc-7mvw4"
Apr 18 03:03:32.564: INFO: Deleting PersistentVolumeClaim "pvc-7mvw4"
... skipping 44 lines ...
Apr 18 03:03:56.112: INFO: PersistentVolumeClaim pvc-5gdkv found but phase is Pending instead of Bound.
Apr 18 03:03:58.215: INFO: PersistentVolumeClaim pvc-5gdkv found and phase=Bound (23.236693232s)
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 03:03:58.524: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-28cnq" in namespace "azurefile-4547" to be "Succeeded or Failed"
Apr 18 03:03:58.626: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Pending", Reason="", readiness=false. Elapsed: 101.884922ms
Apr 18 03:04:00.728: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204515507s
Apr 18 03:04:02.833: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309477562s
Apr 18 03:04:04.939: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.41527666s
Apr 18 03:04:07.045: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.521322221s
Apr 18 03:04:09.151: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Running", Reason="", readiness=true. Elapsed: 10.627487319s
Apr 18 03:04:11.257: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Running", Reason="", readiness=true. Elapsed: 12.733028677s
Apr 18 03:04:13.362: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Running", Reason="", readiness=true. Elapsed: 14.838158217s
Apr 18 03:04:15.468: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Running", Reason="", readiness=true. Elapsed: 16.944614784s
Apr 18 03:04:17.573: INFO: Pod "azurefile-volume-tester-28cnq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.049703733s
STEP: Saw pod success
Apr 18 03:04:17.574: INFO: Pod "azurefile-volume-tester-28cnq" satisfied condition "Succeeded or Failed"
Apr 18 03:04:17.574: INFO: deleting Pod "azurefile-4547"/"azurefile-volume-tester-28cnq"
Apr 18 03:04:17.688: INFO: Pod azurefile-volume-tester-28cnq has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-28cnq in namespace azurefile-4547
Apr 18 03:04:17.802: INFO: deleting PVC "azurefile-4547"/"pvc-5gdkv"
Apr 18 03:04:17.802: INFO: Deleting PersistentVolumeClaim "pvc-5gdkv"
... skipping 73 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 03:05:43 Check successfully
Apr 18 03:05:43.121: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 03:05:43 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 03:05:43 got output: azure-storage-account-f44e0972f9efd4c459bc1ac-secret
, error: <nil>
2022/04/18 03:05:43 got storage account secret name: azure-storage-account-f44e0972f9efd4c459bc1ac-secret
STEP: Successfully provisioned AzureFile volume: "capz-wzptwz#f44e0972f9efd4c459bc1ac#csi-inline-smb-volume##csi-inline-smb-volume"

STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 03:05:45.077: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-jfgrk" in namespace "azurefile-4801" to be "Succeeded or Failed"
Apr 18 03:05:45.178: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Pending", Reason="", readiness=false. Elapsed: 101.752347ms
Apr 18 03:05:47.282: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205514141s
Apr 18 03:05:49.388: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.310903674s
Apr 18 03:05:51.493: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.416076007s
Apr 18 03:05:53.599: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522125367s
Apr 18 03:05:55.704: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Running", Reason="", readiness=true. Elapsed: 10.627639945s
Apr 18 03:05:57.814: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Running", Reason="", readiness=true. Elapsed: 12.737291833s
Apr 18 03:05:59.919: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Running", Reason="", readiness=true. Elapsed: 14.842799911s
Apr 18 03:06:02.025: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Running", Reason="", readiness=true. Elapsed: 16.948706877s
Apr 18 03:06:04.131: INFO: Pod "azurefile-volume-tester-jfgrk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.054553682s
STEP: Saw pod success
Apr 18 03:06:04.131: INFO: Pod "azurefile-volume-tester-jfgrk" satisfied condition "Succeeded or Failed"
Apr 18 03:06:04.131: INFO: deleting Pod "azurefile-4801"/"azurefile-volume-tester-jfgrk"
Apr 18 03:06:04.244: INFO: Pod azurefile-volume-tester-jfgrk has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-jfgrk in namespace azurefile-4801
Apr 18 03:06:04.445: 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/18 03:06:07 Check successfully
Apr 18 03:06:07.699: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: creating secret smbcreds in namespace azurefile-1166
2022/04/18 03:06:07 run script: test/utils/get_smb_svc_public_ip.sh
2022/04/18 03:06:08 got output: 20.123.104.24
, error: <nil>
2022/04/18 03:06:08 use server on Windows: 20.123.104.24
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 03:06:08.389: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7l2mq" in namespace "azurefile-1166" to be "Succeeded or Failed"
Apr 18 03:06:08.491: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Pending", Reason="", readiness=false. Elapsed: 101.576533ms
Apr 18 03:06:10.594: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204241833s
Apr 18 03:06:12.699: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309430058s
Apr 18 03:06:14.804: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.41430602s
Apr 18 03:06:16.910: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.520367446s
Apr 18 03:06:19.016: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Running", Reason="", readiness=true. Elapsed: 10.626465825s
Apr 18 03:06:21.121: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Running", Reason="", readiness=true. Elapsed: 12.731581871s
Apr 18 03:06:23.227: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Running", Reason="", readiness=true. Elapsed: 14.837843941s
Apr 18 03:06:25.333: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Running", Reason="", readiness=true. Elapsed: 16.943814643s
Apr 18 03:06:27.438: INFO: Pod "azurefile-volume-tester-7l2mq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.048881771s
STEP: Saw pod success
Apr 18 03:06:27.438: INFO: Pod "azurefile-volume-tester-7l2mq" satisfied condition "Succeeded or Failed"
Apr 18 03:06:27.438: INFO: deleting Pod "azurefile-1166"/"azurefile-volume-tester-7l2mq"
Apr 18 03:06:27.554: INFO: Pod azurefile-volume-tester-7l2mq has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-7l2mq in namespace azurefile-1166
Apr 18 03:06:27.672: INFO: deleting Secret smbcreds
Apr 18 03:06:27.777: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
... skipping 132 lines ...
Apr 18 03:06:37.064: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-j6cds] to have phase Bound
Apr 18 03:06:37.165: INFO: PersistentVolumeClaim pvc-j6cds found and phase=Bound (101.628728ms)
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 03:06:37.508: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-gm2zn" in namespace "azurefile-5320" to be "Error status code"
Apr 18 03:06:37.610: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Pending", Reason="", readiness=false. Elapsed: 101.790672ms
Apr 18 03:06:39.713: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.2047023s
Apr 18 03:06:41.818: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309707296s
Apr 18 03:06:43.924: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.416043557s
Apr 18 03:06:46.030: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.521456696s
Apr 18 03:06:48.136: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Running", Reason="", readiness=true. Elapsed: 10.627425524s
Apr 18 03:06:50.241: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Running", Reason="", readiness=true. Elapsed: 12.732798625s
Apr 18 03:06:52.347: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Running", Reason="", readiness=true. Elapsed: 14.839096078s
Apr 18 03:06:54.454: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Running", Reason="", readiness=true. Elapsed: 16.945277248s
Apr 18 03:06:56.559: INFO: Pod "azurefile-volume-tester-gm2zn": Phase="Failed", Reason="", readiness=false. Elapsed: 19.050922823s
STEP: Saw pod failure
Apr 18 03:06:56.560: INFO: Pod "azurefile-volume-tester-gm2zn" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 03:06:56.679: INFO: deleting Pod "azurefile-5320"/"azurefile-volume-tester-gm2zn"
Apr 18 03:06:56.786: INFO: Pod azurefile-volume-tester-gm2zn 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 18 03:07:00.871: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-dssqr] to have phase Bound
Apr 18 03:07:00.973: INFO: PersistentVolumeClaim pvc-dssqr found and phase=Bound (102.04471ms)
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 03:07:01.281: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-2sjww" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 03:07:01.383: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Pending", Reason="", readiness=false. Elapsed: 101.942116ms
Apr 18 03:07:03.486: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20524818s
Apr 18 03:07:05.596: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Pending", Reason="", readiness=false. Elapsed: 4.314598902s
Apr 18 03:07:07.702: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Pending", Reason="", readiness=false. Elapsed: 6.420966637s
Apr 18 03:07:09.808: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Pending", Reason="", readiness=false. Elapsed: 8.527185483s
Apr 18 03:07:11.913: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Running", Reason="", readiness=true. Elapsed: 10.631592307s
Apr 18 03:07:14.018: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Running", Reason="", readiness=true. Elapsed: 12.737170411s
Apr 18 03:07:16.124: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Running", Reason="", readiness=true. Elapsed: 14.843068676s
Apr 18 03:07:18.229: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Running", Reason="", readiness=true. Elapsed: 16.947844281s
Apr 18 03:07:20.335: INFO: Pod "azurefile-volume-tester-2sjww": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.053583625s
STEP: Saw pod success
Apr 18 03:07:20.335: INFO: Pod "azurefile-volume-tester-2sjww" 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 03:07:20.540: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-9xwqt] to have phase Bound
Apr 18 03:07:20.642: INFO: PersistentVolumeClaim pvc-9xwqt found and phase=Bound (102.12122ms)
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 03:07:20.950: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-bqrct" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 03:07:21.052: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Pending", Reason="", readiness=false. Elapsed: 101.871591ms
Apr 18 03:07:23.155: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205337258s
Apr 18 03:07:25.262: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Pending", Reason="", readiness=false. Elapsed: 4.311876856s
Apr 18 03:07:27.367: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Pending", Reason="", readiness=false. Elapsed: 6.417372626s
Apr 18 03:07:29.474: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Pending", Reason="", readiness=false. Elapsed: 8.523741466s
Apr 18 03:07:31.579: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Running", Reason="", readiness=true. Elapsed: 10.629287899s
Apr 18 03:07:33.685: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Running", Reason="", readiness=true. Elapsed: 12.735331934s
Apr 18 03:07:35.791: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Running", Reason="", readiness=true. Elapsed: 14.841321113s
Apr 18 03:07:37.898: INFO: Pod "azurefile-volume-tester-bqrct": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.947835549s
STEP: Saw pod success
Apr 18 03:07:37.898: INFO: Pod "azurefile-volume-tester-bqrct" 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 03:07:38.110: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-7jqwn] to have phase Bound
Apr 18 03:07:38.211: INFO: PersistentVolumeClaim pvc-7jqwn found and phase=Bound (101.49234ms)
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 03:07:38.519: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4qwmf" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 03:07:38.623: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Pending", Reason="", readiness=false. Elapsed: 103.798944ms
Apr 18 03:07:40.729: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209552651s
Apr 18 03:07:42.834: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Pending", Reason="", readiness=false. Elapsed: 4.314618425s
Apr 18 03:07:44.939: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Pending", Reason="", readiness=false. Elapsed: 6.420000566s
Apr 18 03:07:47.045: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Pending", Reason="", readiness=false. Elapsed: 8.525857945s
Apr 18 03:07:49.151: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Running", Reason="", readiness=true. Elapsed: 10.631819686s
Apr 18 03:07:51.256: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Running", Reason="", readiness=true. Elapsed: 12.736741328s
Apr 18 03:07:53.362: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Running", Reason="", readiness=true. Elapsed: 14.842081974s
Apr 18 03:07:55.467: INFO: Pod "azurefile-volume-tester-4qwmf": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.947530142s
STEP: Saw pod success
Apr 18 03:07:55.467: INFO: Pod "azurefile-volume-tester-4qwmf" 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 03:07:55.673: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-7b6wm] to have phase Bound
Apr 18 03:07:55.775: INFO: PersistentVolumeClaim pvc-7b6wm found and phase=Bound (101.878486ms)
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 03:07:56.083: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-hvqsq" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 03:07:56.185: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Pending", Reason="", readiness=false. Elapsed: 102.325633ms
Apr 18 03:07:58.287: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204783001s
Apr 18 03:08:00.393: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.31069269s
Apr 18 03:08:02.498: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.415536364s
Apr 18 03:08:04.603: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.520669468s
Apr 18 03:08:06.709: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Running", Reason="", readiness=true. Elapsed: 10.626375778s
Apr 18 03:08:08.815: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Running", Reason="", readiness=true. Elapsed: 12.732798305s
Apr 18 03:08:10.921: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Running", Reason="", readiness=true. Elapsed: 14.838897939s
Apr 18 03:08:13.026: INFO: Pod "azurefile-volume-tester-hvqsq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.943925323s
STEP: Saw pod success
Apr 18 03:08:13.027: INFO: Pod "azurefile-volume-tester-hvqsq" 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 03:08:13.235: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-w9v85] to have phase Bound
Apr 18 03:08:13.336: INFO: PersistentVolumeClaim pvc-w9v85 found and phase=Bound (101.78049ms)
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 03:08:13.644: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vw2s8" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 03:08:13.746: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Pending", Reason="", readiness=false. Elapsed: 101.870179ms
Apr 18 03:08:15.850: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206041465s
Apr 18 03:08:17.956: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.311873186s
Apr 18 03:08:20.062: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.41791821s
Apr 18 03:08:22.167: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.523260295s
Apr 18 03:08:24.273: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Running", Reason="", readiness=true. Elapsed: 10.629434222s
Apr 18 03:08:26.379: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Running", Reason="", readiness=true. Elapsed: 12.73566451s
Apr 18 03:08:28.485: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Running", Reason="", readiness=true. Elapsed: 14.841701178s
Apr 18 03:08:30.592: INFO: Pod "azurefile-volume-tester-vw2s8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.947882007s
STEP: Saw pod success
Apr 18 03:08:30.592: INFO: Pod "azurefile-volume-tester-vw2s8" 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 03:08:30.803: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-tbncw] to have phase Bound
Apr 18 03:08:30.905: INFO: PersistentVolumeClaim pvc-tbncw found and phase=Bound (101.914877ms)
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 03:08:31.212: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8pvst" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 03:08:31.314: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Pending", Reason="", readiness=false. Elapsed: 101.962907ms
Apr 18 03:08:33.417: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205072115s
Apr 18 03:08:35.523: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Pending", Reason="", readiness=false. Elapsed: 4.310595518s
Apr 18 03:08:37.629: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Pending", Reason="", readiness=false. Elapsed: 6.4167229s
Apr 18 03:08:39.735: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Pending", Reason="", readiness=false. Elapsed: 8.522992074s
Apr 18 03:08:41.841: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Running", Reason="", readiness=true. Elapsed: 10.628942953s
Apr 18 03:08:43.947: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Running", Reason="", readiness=true. Elapsed: 12.735133734s
Apr 18 03:08:46.053: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Running", Reason="", readiness=true. Elapsed: 14.84072826s
Apr 18 03:08:48.159: INFO: Pod "azurefile-volume-tester-8pvst": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.94665457s
STEP: Saw pod success
Apr 18 03:08:48.159: INFO: Pod "azurefile-volume-tester-8pvst" satisfied condition "Succeeded or Failed"
Apr 18 03:08:48.159: INFO: deleting Pod "azurefile-9103"/"azurefile-volume-tester-8pvst"
Apr 18 03:08:48.283: INFO: Pod azurefile-volume-tester-8pvst has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-8pvst in namespace azurefile-9103
Apr 18 03:08:48.393: INFO: deleting PVC "azurefile-9103"/"pvc-tbncw"
Apr 18 03:08:48.393: INFO: Deleting PersistentVolumeClaim "pvc-tbncw"
... skipping 148 lines ...
Apr 18 03:09:00.756: INFO: PersistentVolumeClaim pvc-jvlv5 found but phase is Pending instead of Bound.
Apr 18 03:09:02.858: INFO: PersistentVolumeClaim pvc-jvlv5 found and phase=Bound (2.206309498s)
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 03:09:03.166: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-79jwp" in namespace "azurefile-8470" to be "Succeeded or Failed"
Apr 18 03:09:03.268: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Pending", Reason="", readiness=false. Elapsed: 102.078807ms
Apr 18 03:09:05.371: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20546451s
Apr 18 03:09:07.477: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Pending", Reason="", readiness=false. Elapsed: 4.31140323s
Apr 18 03:09:09.583: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Pending", Reason="", readiness=false. Elapsed: 6.417052875s
Apr 18 03:09:11.688: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Pending", Reason="", readiness=false. Elapsed: 8.521954607s
Apr 18 03:09:13.794: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Pending", Reason="", readiness=false. Elapsed: 10.627840346s
Apr 18 03:09:15.899: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Running", Reason="", readiness=true. Elapsed: 12.732968302s
Apr 18 03:09:18.005: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Running", Reason="", readiness=true. Elapsed: 14.83903903s
Apr 18 03:09:20.110: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Running", Reason="", readiness=true. Elapsed: 16.944641393s
Apr 18 03:09:22.220: INFO: Pod "azurefile-volume-tester-79jwp": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.0539292s
STEP: Saw pod success
Apr 18 03:09:22.220: INFO: Pod "azurefile-volume-tester-79jwp" satisfied condition "Succeeded or Failed"
Apr 18 03:09:22.220: INFO: deleting Pod "azurefile-8470"/"azurefile-volume-tester-79jwp"
Apr 18 03:09:22.332: INFO: Pod azurefile-volume-tester-79jwp has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-79jwp in namespace azurefile-8470
Apr 18 03:09:22.532: INFO: deleting PVC "azurefile-8470"/"pvc-jvlv5"
Apr 18 03:09:22.532: INFO: Deleting PersistentVolumeClaim "pvc-jvlv5"
... skipping 33 lines ...
Apr 18 03:09:26.329: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-khsw5] to have phase Bound
Apr 18 03:09:26.431: INFO: PersistentVolumeClaim pvc-khsw5 found and phase=Bound (101.823981ms)
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 03:09:26.737: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qw6k8" in namespace "azurefile-7029" to be "Succeeded or Failed"
Apr 18 03:09:26.839: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Pending", Reason="", readiness=false. Elapsed: 101.382036ms
Apr 18 03:09:28.942: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.2044897s
Apr 18 03:09:31.047: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.309954991s
Apr 18 03:09:33.153: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.415463389s
Apr 18 03:09:35.259: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.521073324s
Apr 18 03:09:37.364: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.626880235s
Apr 18 03:09:39.470: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Running", Reason="", readiness=true. Elapsed: 12.732236574s
Apr 18 03:09:41.576: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Running", Reason="", readiness=true. Elapsed: 14.838075683s
Apr 18 03:09:43.682: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Running", Reason="", readiness=true. Elapsed: 16.94409818s
Apr 18 03:09:45.788: INFO: Pod "azurefile-volume-tester-qw6k8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 19.050180989s
STEP: Saw pod success
Apr 18 03:09:45.788: INFO: Pod "azurefile-volume-tester-qw6k8" satisfied condition "Succeeded or Failed"
Apr 18 03:09:45.788: INFO: deleting Pod "azurefile-7029"/"azurefile-volume-tester-qw6k8"
Apr 18 03:09:45.900: INFO: Pod azurefile-volume-tester-qw6k8 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-qw6k8 in namespace azurefile-7029
Apr 18 03:09:46.011: INFO: deleting PVC "azurefile-7029"/"pvc-khsw5"
Apr 18 03:09:46.011: INFO: Deleting PersistentVolumeClaim "pvc-khsw5"
... skipping 86 lines ...
Platform: linux/amd64

Streaming logs below:
I0418 02:47:03.274357       1 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-92b6b36980c6d5b3569bdf7138de57ac800caf1c gc/go1.18.1 (amd64-linux) e2e-test
I0418 02:47:03.274840       1 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 02:47:03.284205       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 9 milliseconds
W0418 02:47:03.284433       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 02:47:03.284449       1 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 02:47:03.284458       1 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0418 02:47:03.284489       1 azure.go:101] read cloud config from file: /etc/kubernetes/azure.json successfully
I0418 02:47:03.284924       1 azure_auth.go:245] Using AzurePublicCloud environment
I0418 02:47:03.284965       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 02:47:03.285022       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 2920 lines ...
Platform: windows/amd64

Streaming logs below:
I0418 02:47:36.169862    6840 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-92b6b36980c6d5b3569bdf7138de57ac800caf1c gc/go1.18.1 (amd64-windows) e2e-test
I0418 02:47:36.185356    6840 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 02:47:36.191185    6840 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider  in 2 milliseconds
W0418 02:47:36.191912    6840 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: Get "https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider": dial tcp 10.96.0.1:443: connectex: An attempt was made to access a socket in a way forbidden by its access permissions.
I0418 02:47:36.191912    6840 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 02:47:36.191912    6840 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0418 02:47:36.191912    6840 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0418 02:47:36.200512    6840 azure_auth.go:245] Using AzurePublicCloud environment
I0418 02:47:36.201831    6840 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 02:47:36.203991    6840 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 53 lines ...
I0418 02:49:44.750864    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:44.751637    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:44.751908    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:44.752511    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:44.752511    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:49:44.755153    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:49:50.815188    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:49:51.395766    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:49:51.395766    6840 utils.go:77] GRPC request: {}
I0418 02:49:51.395766    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 02:49:51.398589    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:49:51.398589    6840 utils.go:77] GRPC request: {}
I0418 02:49:51.398589    6840 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 02:49:51.405936    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:51.406685    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:51.406685    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:51.407370    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:51.407416    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:49:51.408074    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:49:53.773086    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:49:54.736915    6840 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 02:49:54.736915    6840 utils.go:77] GRPC request: {}
I0418 02:49:54.736915    6840 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 02:49:54.836237    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:49:54.836824    6840 utils.go:77] GRPC request: {}
I0418 02:49:54.836922    6840 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 02:49:54.846933    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:54.847144    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:54.847144    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:54.848107    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:54.848148    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:49:54.848635    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:49:57.182043    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:49:59.189819    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:49:59.189819    6840 utils.go:77] GRPC request: {}
I0418 02:49:59.189819    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 02:49:59.193535    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:49:59.193591    6840 utils.go:77] GRPC request: {}
I0418 02:49:59.193674    6840 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 02:49:59.199960    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:59.200642    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:59.200642    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:59.204161    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:49:59.204196    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:49:59.204376    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:50:01.549346    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:50:05.588950    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:50:05.588983    6840 utils.go:77] GRPC request: {}
I0418 02:50:05.589014    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 02:50:05.592453    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:50:05.592453    6840 utils.go:77] GRPC request: {}
I0418 02:50:05.593382    6840 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 02:50:05.598186    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:05.598707    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:05.598777    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:05.599038    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:05.599038    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:50:05.599823    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:50:07.993691    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:50:16.069090    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:50:16.069090    6840 utils.go:77] GRPC request: {}
I0418 02:50:16.069090    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 02:50:16.072197    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:50:16.072197    6840 utils.go:77] GRPC request: {}
I0418 02:50:16.072197    6840 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 02:50:16.077037    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:16.077276    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:16.077276    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:16.078238    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:16.078264    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:50:16.078440    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:50:18.488710    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:50:24.728215    6840 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 02:50:24.728215    6840 utils.go:77] GRPC request: {}
I0418 02:50:24.728215    6840 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 02:50:34.498837    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:50:34.498837    6840 utils.go:77] GRPC request: {}
I0418 02:50:34.498837    6840 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 02:50:34.510487    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:34.510951    6840 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:34.510951    6840 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:34.511681    6840 safe_mounter_windows.go:70] SMBMount: remote path: \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
I0418 02:50:34.511719    6840 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1
I0418 02:50:34.511904    6840 safe_mounter_windows.go:97] begin to mount \\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\globalmount
E0418 02:50:36.941500    6840 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-wzptwz#feaad6c8efc5c4919b94e75#pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1#) mount "\\\\feaad6c8efc5c4919b94e75.privatelink.file.core.windows.net\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-a4475065-e3d0-4727-ac8f-d5830b4e66d1\\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 02:50:54.740285    6840 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 02:50:54.740813    6840 utils.go:77] GRPC request: {}
I0418 02:50:54.740967    6840 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 02:51:08.989594    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 02:51:08.989594    6840 utils.go:77] GRPC request: {}
I0418 02:51:08.990186    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 1201 lines ...
I0418 03:05:45.317655    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 03:05:45.317655    6840 utils.go:77] GRPC request: {}
I0418 03:05:45.317655    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 03:05:45.321773    6840 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0418 03:05:45.321773    6840 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\\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-jfgrk","csi.storage.k8s.io/pod.namespace":"azurefile-4801","csi.storage.k8s.io/pod.uid":"bdb2c30f-8918-4257-bf5b-7fc0e74236f5","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"azure-storage-account-f44e0972f9efd4c459bc1ac-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-a124714b87def9b418b52f66304ba9def8f200e9e49e6fe2dfa8576e042458fd"}
I0418 03:05:45.321773    6840 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-a124714b87def9b418b52f66304ba9def8f200e9e49e6fe2dfa8576e042458fd) mount on c:\var\lib\kubelet\pods\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\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-jfgrk csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:bdb2c30f-8918-4257-bf5b-7fc0e74236f5 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f44e0972f9efd4c459bc1ac-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]
W0418 03:05:45.321773    6840 azurefile.go:546] parsing volumeID(csi-a124714b87def9b418b52f66304ba9def8f200e9e49e6fe2dfa8576e042458fd) return with error: error parsing volume id: "csi-a124714b87def9b418b52f66304ba9def8f200e9e49e6fe2dfa8576e042458fd", should at least contain two #
I0418 03:05:45.335065    6840 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-4801/secrets/azure-storage-account-f44e0972f9efd4c459bc1ac-secret 200 OK in 12 milliseconds
I0418 03:05:45.335065    6840 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-a124714b87def9b418b52f66304ba9def8f200e9e49e6fe2dfa8576e042458fd) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-jfgrk csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:bdb2c30f-8918-4257-bf5b-7fc0e74236f5 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f44e0972f9efd4c459bc1ac-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\f44e0972f9efd4c459bc1ac]) volumeMountGroup()
I0418 03:05:45.335065    6840 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 03:05:45.335065    6840 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 03:05:45.337328    6840 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 03:05:45.338068    6840 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\bdb2c30f-8918-4257-bf5b-7fc0e74236f5\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 20 lines ...
I0418 03:06:08.641592    6840 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 03:06:08.641592    6840 utils.go:77] GRPC request: {}
I0418 03:06:08.641592    6840 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 03:06:08.644425    6840 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0418 03:06:08.644472    6840 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\94894751-464d-4de2-a98c-3c96615b4294\\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-7l2mq","csi.storage.k8s.io/pod.namespace":"azurefile-1166","csi.storage.k8s.io/pod.uid":"94894751-464d-4de2-a98c-3c96615b4294","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"smbcreds","server":"20.123.104.24","shareName":"share"},"volume_id":"csi-266af67efcc10d78dad4389dd3db408092e14d7a3563c08b5e0cde816dab7469"}
I0418 03:06:08.644734    6840 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-266af67efcc10d78dad4389dd3db408092e14d7a3563c08b5e0cde816dab7469) mount on c:\var\lib\kubelet\pods\94894751-464d-4de2-a98c-3c96615b4294\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-7l2mq csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:94894751-464d-4de2-a98c-3c96615b4294 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:20.123.104.24 shareName:share storageaccount:]
W0418 03:06:08.644838    6840 azurefile.go:546] parsing volumeID(csi-266af67efcc10d78dad4389dd3db408092e14d7a3563c08b5e0cde816dab7469) return with error: error parsing volume id: "csi-266af67efcc10d78dad4389dd3db408092e14d7a3563c08b5e0cde816dab7469", should at least contain two #
I0418 03:06:08.648272    6840 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-1166/secrets/smbcreds 200 OK in 3 milliseconds
I0418 03:06:08.648272    6840 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\94894751-464d-4de2-a98c-3c96615b4294\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-266af67efcc10d78dad4389dd3db408092e14d7a3563c08b5e0cde816dab7469) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-7l2mq csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:94894751-464d-4de2-a98c-3c96615b4294 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:20.123.104.24 shareName:share storageaccount:]) mountflags([]) mountOptions([AZURE\USERNAME]) volumeMountGroup()
I0418 03:06:08.648272    6840 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\94894751-464d-4de2-a98c-3c96615b4294\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 03:06:08.648272    6840 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\94894751-464d-4de2-a98c-3c96615b4294\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 03:06:08.650509    6840 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\94894751-464d-4de2-a98c-3c96615b4294\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 03:06:08.650726    6840 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\94894751-464d-4de2-a98c-3c96615b4294\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 731 lines ...
Platform: windows/amd64

Streaming logs below:
I0418 02:47:38.555925    6844 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-92b6b36980c6d5b3569bdf7138de57ac800caf1c gc/go1.18.1 (amd64-windows) e2e-test
I0418 02:47:38.565818    6844 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 02:47:38.596193    6844 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
W0418 02:47:38.596825    6844 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 02:47:38.596825    6844 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 02:47:38.596825    6844 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0418 02:47:38.597352    6844 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0418 02:47:38.602560    6844 azure_auth.go:245] Using AzurePublicCloud environment
I0418 02:47:38.603180    6844 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 02:47:38.603748    6844 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 580 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 1482.238 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 (1482.25s)
FAIL
FAIL	sigs.k8s.io/azurefile-csi-driver/test/e2e	1482.336s
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 99 lines ...