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 06:39
Elapsed47m45s
Revision406a0d30aff10d48525d3e58710a2b1ac4047aa0
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] 10m4s

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


Show 19 Passed Tests

Show 14 Skipped Tests

Error lines from build-log.txt

... skipping 673 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-0q4s14-kubeconfig; do sleep 1; done"
capz-0q4s14-kubeconfig                 cluster.x-k8s.io/secret               1      1s
# Get kubeconfig and store it locally.
kubectl get secrets capz-0q4s14-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-0q4s14-control-plane-qqx8m   NotReady   control-plane,master   14s   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-0q4s-2wxn5 condition met
node/capz-0q4s-k2x4l condition met
... skipping 1021 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:
W0418 06:56:59.969028   36376 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
I0418 06:56:59.974293   36376 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0418 06:56:59.974316   36376 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0418 06:56:59.974321   36376 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0418 06:56:59.974325   36376 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0418 06:56:59.974329   36376 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
... skipping 126 lines ...
Apr 18 06:59:13.402: INFO: PersistentVolumeClaim pvc-zpr6j found and phase=Bound (1m41.677381189s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 06:59:14.501: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-ptt4m" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 06:59:14.533: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 32.253518ms
Apr 18 06:59:16.566: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064955657s
Apr 18 06:59:18.599: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098240997s
Apr 18 06:59:20.631: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.130737002s
Apr 18 06:59:22.664: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.163446286s
Apr 18 06:59:24.697: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 10.196319256s
... skipping 231 lines ...
Apr 18 07:07:16.527: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8m2.026491569s
Apr 18 07:07:18.562: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8m4.060940334s
Apr 18 07:07:20.596: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8m6.094983012s
Apr 18 07:07:22.630: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8m8.129372626s
Apr 18 07:07:24.663: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8m10.162207645s
Apr 18 07:07:26.697: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8m12.196741577s
Apr 18 07:07:28.731: INFO: Pod "azurefile-volume-tester-ptt4m": Phase="Failed", Reason="", readiness=false. Elapsed: 8m14.23019134s
Apr 18 07:07:28.732: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-ptt4m"
Apr 18 07:07:28.780: INFO: Pod azurefile-volume-tester-ptt4m has the following logs: 
STEP: Deleting pod azurefile-volume-tester-ptt4m in namespace azurefile-2540
Apr 18 07:07:28.819: INFO: deleting PVC "azurefile-2540"/"pvc-zpr6j"
Apr 18 07:07:28.819: INFO: Deleting PersistentVolumeClaim "pvc-zpr6j"
STEP: waiting for claim's PV "pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" to be deleted
... skipping 6 lines ...
STEP: Collecting events from namespace "azurefile-2540".
STEP: Found 12 events.
Apr 18 07:07:34.089: INFO: At 2022-04-18 06:57:31 +0000 UTC - event for pvc-zpr6j: {file.csi.azure.com_capz-0q4s14-md-0-dv5vf_5dceabea-fd5e-4ea4-a6a9-4b3d62517ccd } Provisioning: External provisioner is provisioning volume for claim "azurefile-2540/pvc-zpr6j"
Apr 18 07:07:34.089: INFO: At 2022-04-18 06:57:31 +0000 UTC - event for pvc-zpr6j: {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 07:07:34.089: INFO: At 2022-04-18 06:59:11 +0000 UTC - event for pvc-zpr6j: {file.csi.azure.com_capz-0q4s14-md-0-dv5vf_5dceabea-fd5e-4ea4-a6a9-4b3d62517ccd } ProvisioningSucceeded: Successfully provisioned volume pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
Apr 18 07:07:34.089: INFO: At 2022-04-18 06:59:13 +0000 UTC - event for azurefile-volume-tester-ptt4m: {default-scheduler } Scheduled: Successfully assigned azurefile-2540/azurefile-volume-tester-ptt4m to capz-0q4s-2wxn5
Apr 18 07:07:34.089: INFO: At 2022-04-18 06:59:20 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} FailedMount: MountVolume.MountDevice failed for volume "pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" : rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 07:07:34.089: INFO: At 2022-04-18 07:00:44 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 18 07:07:34.089: INFO: At 2022-04-18 07:05:27 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m42.4697524s
Apr 18 07:07:34.089: INFO: At 2022-04-18 07:05:27 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Created: Created container volume-tester
Apr 18 07:07:34.089: INFO: At 2022-04-18 07:07:27 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Failed: Error: context deadline exceeded
Apr 18 07:07:34.089: INFO: At 2022-04-18 07:07:28 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 18 07:07:34.089: INFO: At 2022-04-18 07:07:32 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Started: Started container volume-tester
Apr 18 07:07:34.089: INFO: At 2022-04-18 07:07:33 +0000 UTC - event for azurefile-volume-tester-ptt4m: {kubelet capz-0q4s-2wxn5} Killing: Stopping container volume-tester
Apr 18 07:07:34.121: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 07:07:34.121: INFO: 
Apr 18 07:07:34.164: INFO: 
... skipping 115 lines ...
• Failure [604.654 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 | 0xc000b49b20>: {
          s: "pod \"azurefile-volume-tester-ptt4m\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 06:59:13 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 06:59:13 +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 06:59:13 +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 06:59:13 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.3.196 PodIPs:[{IP:192.168.3.196}] StartTime:2022-04-18 06:59:13 +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://c41d650d1059ef8b910fcc224fe47935014410ea85c06516d4f7a357d9119bd1,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://c41d650d1059ef8b910fcc224fe47935014410ea85c06516d4f7a357d9119bd1 Started:0xc0007071d8}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
      }
      pod "azurefile-volume-tester-ptt4m" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 06:59:13 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-18 06:59:13 +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 06:59:13 +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 06:59:13 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.3.196 PodIPs:[{IP:192.168.3.196}] StartTime:2022-04-18 06:59:13 +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://c41d650d1059ef8b910fcc224fe47935014410ea85c06516d4f7a357d9119bd1,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://c41d650d1059ef8b910fcc224fe47935014410ea85c06516d4f7a357d9119bd1 Started:0xc0007071d8}] 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 28 lines ...
Apr 18 07:07:58.982: INFO: PersistentVolumeClaim pvc-wfws4 found but phase is Pending instead of Bound.
Apr 18 07:08:01.015: INFO: PersistentVolumeClaim pvc-wfws4 found and phase=Bound (24.42475701s)
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 07:08:01.121: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-kwhf4" in namespace "azurefile-4728" to be "Succeeded or Failed"
Apr 18 07:08:01.165: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Pending", Reason="", readiness=false. Elapsed: 43.723712ms
Apr 18 07:08:03.197: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076182406s
Apr 18 07:08:05.231: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.109744147s
Apr 18 07:08:07.264: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.142984126s
Apr 18 07:08:09.297: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.176212948s
Apr 18 07:08:11.331: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209722002s
... skipping 2 lines ...
Apr 18 07:08:17.431: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Running", Reason="", readiness=true. Elapsed: 16.309471667s
Apr 18 07:08:19.464: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Running", Reason="", readiness=true. Elapsed: 18.343211759s
Apr 18 07:08:21.498: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Running", Reason="", readiness=true. Elapsed: 20.376411684s
Apr 18 07:08:23.531: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Running", Reason="", readiness=true. Elapsed: 22.409410485s
Apr 18 07:08:25.564: INFO: Pod "azurefile-volume-tester-kwhf4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 24.442605833s
STEP: Saw pod success
Apr 18 07:08:25.564: INFO: Pod "azurefile-volume-tester-kwhf4" satisfied condition "Succeeded or Failed"
Apr 18 07:08:25.564: INFO: deleting Pod "azurefile-4728"/"azurefile-volume-tester-kwhf4"
Apr 18 07:08:25.605: INFO: Pod azurefile-volume-tester-kwhf4 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-kwhf4 in namespace azurefile-4728
Apr 18 07:08:25.665: INFO: deleting PVC "azurefile-4728"/"pvc-wfws4"
Apr 18 07:08:25.665: INFO: Deleting PersistentVolumeClaim "pvc-wfws4"
... skipping 116 lines ...
Apr 18 07:09:29.654: INFO: PersistentVolumeClaim pvc-rb7ll found but phase is Pending instead of Bound.
Apr 18 07:09:31.687: INFO: PersistentVolumeClaim pvc-rb7ll found and phase=Bound (20.358966142s)
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 07:09:31.784: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-wq4bw" in namespace "azurefile-2790" to be "Error status code"
Apr 18 07:09:31.819: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 34.790741ms
Apr 18 07:09:33.851: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067269258s
Apr 18 07:09:35.884: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.100422653s
Apr 18 07:09:37.918: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133739426s
Apr 18 07:09:39.951: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166547698s
Apr 18 07:09:41.985: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.200600422s
Apr 18 07:09:44.018: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Pending", Reason="", readiness=false. Elapsed: 12.233931925s
Apr 18 07:09:46.051: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Running", Reason="", readiness=true. Elapsed: 14.267409218s
Apr 18 07:09:48.086: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Running", Reason="", readiness=true. Elapsed: 16.301591391s
Apr 18 07:09:50.119: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Running", Reason="", readiness=true. Elapsed: 18.335192937s
Apr 18 07:09:52.153: INFO: Pod "azurefile-volume-tester-wq4bw": Phase="Failed", Reason="", readiness=false. Elapsed: 20.368840106s
STEP: Saw pod failure
Apr 18 07:09:52.153: INFO: Pod "azurefile-volume-tester-wq4bw" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 07:09:52.206: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-wq4bw"
Apr 18 07:09:52.241: INFO: Pod azurefile-volume-tester-wq4bw has the following logs: out-file : Access to the path 'C:\mnt\test-1\data' is denied.
At line:1 char:1
+ echo $null >> C:\mnt\test-1\data
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
... skipping 201 lines ...
Apr 18 07:11:11.511: INFO: PersistentVolumeClaim pvc-plssh found but phase is Pending instead of Bound.
Apr 18 07:11:13.545: INFO: PersistentVolumeClaim pvc-plssh found and phase=Bound (2.064649322s)
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 07:11:13.642: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-pk9bk" in namespace "azurefile-4538" to be "Succeeded or Failed"
Apr 18 07:11:13.678: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Pending", Reason="", readiness=false. Elapsed: 35.585676ms
Apr 18 07:11:15.711: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069407574s
Apr 18 07:11:17.745: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.103360009s
Apr 18 07:11:19.779: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.137169156s
Apr 18 07:11:21.812: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.170030955s
Apr 18 07:11:23.846: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.203601274s
Apr 18 07:11:25.879: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Running", Reason="", readiness=true. Elapsed: 12.236850159s
Apr 18 07:11:27.912: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Running", Reason="", readiness=true. Elapsed: 14.270297839s
Apr 18 07:11:29.946: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Running", Reason="", readiness=true. Elapsed: 16.303751427s
Apr 18 07:11:31.987: INFO: Pod "azurefile-volume-tester-pk9bk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.344561224s
STEP: Saw pod success
Apr 18 07:11:31.987: INFO: Pod "azurefile-volume-tester-pk9bk" 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 07:12:02.544: INFO: deleting Pod "azurefile-4538"/"azurefile-volume-tester-pk9bk"
... skipping 303 lines ...
Apr 18 07:12:24.166: INFO: PersistentVolumeClaim pvc-grm52 found but phase is Pending instead of Bound.
Apr 18 07:12:26.199: INFO: PersistentVolumeClaim pvc-grm52 found and phase=Bound (2.064046116s)
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 07:12:26.296: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-z2sg7" in namespace "azurefile-7726" to be "Succeeded or Failed"
Apr 18 07:12:26.332: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 36.343086ms
Apr 18 07:12:28.365: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069577006s
Apr 18 07:12:30.399: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.102715414s
Apr 18 07:12:32.432: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.136347866s
Apr 18 07:12:34.466: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.170447484s
Apr 18 07:12:36.500: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204436134s
Apr 18 07:12:38.534: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 12.237888804s
Apr 18 07:12:40.568: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Pending", Reason="", readiness=false. Elapsed: 14.271695648s
Apr 18 07:12:42.601: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Running", Reason="", readiness=true. Elapsed: 16.30548101s
Apr 18 07:12:44.635: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Running", Reason="", readiness=true. Elapsed: 18.339019933s
Apr 18 07:12:46.669: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Running", Reason="", readiness=true. Elapsed: 20.372989665s
Apr 18 07:12:48.702: INFO: Pod "azurefile-volume-tester-z2sg7": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.405624462s
STEP: Saw pod success
Apr 18 07:12:48.702: INFO: Pod "azurefile-volume-tester-z2sg7" satisfied condition "Succeeded or Failed"
Apr 18 07:12:48.702: INFO: deleting Pod "azurefile-7726"/"azurefile-volume-tester-z2sg7"
Apr 18 07:12:49.104: INFO: Pod azurefile-volume-tester-z2sg7 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-z2sg7 in namespace azurefile-7726
Apr 18 07:12:49.151: INFO: deleting PVC "azurefile-7726"/"pvc-grm52"
Apr 18 07:12:49.152: INFO: Deleting PersistentVolumeClaim "pvc-grm52"
... skipping 96 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 07:13:21 Check successfully
Apr 18 07:13:21.739: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 07:13:21 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 07:13:21 got output: azure-storage-account-f17e239939bcb4a87812841-secret
, error: <nil>
2022/04/18 07:13:21 got storage account secret name: azure-storage-account-f17e239939bcb4a87812841-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"
... skipping 2 lines ...
Apr 18 07:13:24.090: INFO: PersistentVolumeClaim pvc-t4lrz found and phase=Bound (2.069017928s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 07:13:25.190: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-xpwwb" in namespace "azurefile-1387" to be "Succeeded or Failed"
Apr 18 07:13:25.223: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Pending", Reason="", readiness=false. Elapsed: 32.588706ms
Apr 18 07:13:27.255: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064763544s
Apr 18 07:13:29.289: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.099169246s
Apr 18 07:13:31.324: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133450163s
Apr 18 07:13:33.357: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167175388s
Apr 18 07:13:35.391: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Running", Reason="", readiness=true. Elapsed: 10.200443533s
Apr 18 07:13:37.425: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Running", Reason="", readiness=true. Elapsed: 12.234472016s
Apr 18 07:13:39.459: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Running", Reason="", readiness=true. Elapsed: 14.268660704s
Apr 18 07:13:41.493: INFO: Pod "azurefile-volume-tester-xpwwb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.30305664s
STEP: Saw pod success
Apr 18 07:13:41.493: INFO: Pod "azurefile-volume-tester-xpwwb" satisfied condition "Succeeded or Failed"
Apr 18 07:13:41.493: INFO: deleting Pod "azurefile-1387"/"azurefile-volume-tester-xpwwb"
Apr 18 07:13:41.535: INFO: Pod azurefile-volume-tester-xpwwb has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-xpwwb in namespace azurefile-1387
Apr 18 07:13:41.573: INFO: deleting PVC "azurefile-1387"/"pvc-t4lrz"
Apr 18 07:13:41.574: INFO: Deleting PersistentVolumeClaim "pvc-t4lrz"
... skipping 46 lines ...
Apr 18 07:14:09.875: INFO: PersistentVolumeClaim pvc-wbctx found and phase=Bound (22.395957613s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 07:14:10.974: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-hs9zj" in namespace "azurefile-4547" to be "Succeeded or Failed"
Apr 18 07:14:11.006: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Pending", Reason="", readiness=false. Elapsed: 32.005395ms
Apr 18 07:14:13.039: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065101136s
Apr 18 07:14:15.072: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098420767s
Apr 18 07:14:17.106: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132455115s
Apr 18 07:14:19.141: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167161465s
Apr 18 07:14:21.176: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Running", Reason="", readiness=true. Elapsed: 10.202005476s
Apr 18 07:14:23.210: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Running", Reason="", readiness=true. Elapsed: 12.236529289s
Apr 18 07:14:25.244: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Running", Reason="", readiness=true. Elapsed: 14.270036599s
Apr 18 07:14:27.285: INFO: Pod "azurefile-volume-tester-hs9zj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.310750705s
STEP: Saw pod success
Apr 18 07:14:27.285: INFO: Pod "azurefile-volume-tester-hs9zj" satisfied condition "Succeeded or Failed"
Apr 18 07:14:27.285: INFO: deleting Pod "azurefile-4547"/"azurefile-volume-tester-hs9zj"
Apr 18 07:14:27.326: INFO: Pod azurefile-volume-tester-hs9zj has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-hs9zj in namespace azurefile-4547
Apr 18 07:14:27.368: INFO: deleting PVC "azurefile-4547"/"pvc-wbctx"
Apr 18 07:14:27.368: INFO: Deleting PersistentVolumeClaim "pvc-wbctx"
... skipping 74 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 07:15:53 Check successfully
Apr 18 07:15:53.338: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 07:15:53 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 07:15:53 got output: azure-storage-account-f17e239939bcb4a87812841-secret
, error: <nil>
2022/04/18 07:15:53 got storage account secret name: azure-storage-account-f17e239939bcb4a87812841-secret
STEP: Successfully provisioned AzureFile volume: "capz-0q4s14#f17e239939bcb4a87812841#csi-inline-smb-volume##csi-inline-smb-volume"

STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 07:15:54.595: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qwf9j" in namespace "azurefile-4801" to be "Succeeded or Failed"
Apr 18 07:15:54.627: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Pending", Reason="", readiness=false. Elapsed: 31.508892ms
Apr 18 07:15:56.659: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Pending", Reason="", readiness=false. Elapsed: 2.063951709s
Apr 18 07:15:58.693: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Pending", Reason="", readiness=false. Elapsed: 4.09745006s
Apr 18 07:16:00.726: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Pending", Reason="", readiness=false. Elapsed: 6.13104345s
Apr 18 07:16:02.760: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Pending", Reason="", readiness=false. Elapsed: 8.164526578s
Apr 18 07:16:04.794: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Pending", Reason="", readiness=false. Elapsed: 10.198994001s
Apr 18 07:16:06.828: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Running", Reason="", readiness=true. Elapsed: 12.23252329s
Apr 18 07:16:08.862: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Running", Reason="", readiness=true. Elapsed: 14.266730807s
Apr 18 07:16:10.898: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Running", Reason="", readiness=true. Elapsed: 16.303168721s
Apr 18 07:16:12.932: INFO: Pod "azurefile-volume-tester-qwf9j": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.336836315s
STEP: Saw pod success
Apr 18 07:16:12.932: INFO: Pod "azurefile-volume-tester-qwf9j" satisfied condition "Succeeded or Failed"
Apr 18 07:16:12.932: INFO: deleting Pod "azurefile-4801"/"azurefile-volume-tester-qwf9j"
Apr 18 07:16:12.973: INFO: Pod azurefile-volume-tester-qwf9j has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-qwf9j in namespace azurefile-4801
Apr 18 07:16:13.012: 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 07:16:14 Check successfully
Apr 18 07:16:14.160: 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 07:16:14 run script: test/utils/get_smb_svc_public_ip.sh
2022/04/18 07:16:14 got output: 20.85.1.211
, error: <nil>
2022/04/18 07:16:14 use server on Windows: 20.85.1.211
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 07:16:14.450: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qlkwj" in namespace "azurefile-1166" to be "Succeeded or Failed"
Apr 18 07:16:14.482: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Pending", Reason="", readiness=false. Elapsed: 31.62656ms
Apr 18 07:16:16.515: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065109357s
Apr 18 07:16:18.550: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.099241985s
Apr 18 07:16:20.583: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.13286366s
Apr 18 07:16:22.617: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166271347s
Apr 18 07:16:24.651: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Running", Reason="", readiness=true. Elapsed: 10.200670625s
Apr 18 07:16:26.685: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Running", Reason="", readiness=true. Elapsed: 12.235049554s
Apr 18 07:16:28.720: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Running", Reason="", readiness=true. Elapsed: 14.26948003s
Apr 18 07:16:30.753: INFO: Pod "azurefile-volume-tester-qlkwj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.302808901s
STEP: Saw pod success
Apr 18 07:16:30.753: INFO: Pod "azurefile-volume-tester-qlkwj" satisfied condition "Succeeded or Failed"
Apr 18 07:16:30.753: INFO: deleting Pod "azurefile-1166"/"azurefile-volume-tester-qlkwj"
Apr 18 07:16:30.794: INFO: Pod azurefile-volume-tester-qlkwj has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-qlkwj in namespace azurefile-1166
Apr 18 07:16:30.832: INFO: deleting Secret smbcreds
Apr 18 07:16:30.867: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
... skipping 132 lines ...
Apr 18 07:16:58.161: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-p9f6m] to have phase Bound
Apr 18 07:16:58.193: INFO: PersistentVolumeClaim pvc-p9f6m found and phase=Bound (31.693001ms)
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 07:16:58.289: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-9rls9" in namespace "azurefile-5320" to be "Error status code"
Apr 18 07:16:58.321: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Pending", Reason="", readiness=false. Elapsed: 31.593591ms
Apr 18 07:17:00.353: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064264558s
Apr 18 07:17:02.387: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.09761062s
Apr 18 07:17:04.421: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.131728578s
Apr 18 07:17:06.455: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166364662s
Apr 18 07:17:08.489: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Pending", Reason="", readiness=false. Elapsed: 10.200000663s
Apr 18 07:17:10.522: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Running", Reason="", readiness=true. Elapsed: 12.233188532s
Apr 18 07:17:12.556: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Running", Reason="", readiness=true. Elapsed: 14.267333847s
Apr 18 07:17:14.591: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Running", Reason="", readiness=true. Elapsed: 16.302112191s
Apr 18 07:17:16.625: INFO: Pod "azurefile-volume-tester-9rls9": Phase="Failed", Reason="", readiness=false. Elapsed: 18.335754216s
STEP: Saw pod failure
Apr 18 07:17:16.625: INFO: Pod "azurefile-volume-tester-9rls9" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 07:17:16.667: INFO: deleting Pod "azurefile-5320"/"azurefile-volume-tester-9rls9"
Apr 18 07:17:16.704: INFO: Pod azurefile-volume-tester-9rls9 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 07:17:18.327: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-xx97k] to have phase Bound
Apr 18 07:17:18.358: INFO: PersistentVolumeClaim pvc-xx97k found and phase=Bound (31.292425ms)
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 07:17:18.455: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-h9bnp" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 07:17:18.486: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Pending", Reason="", readiness=false. Elapsed: 31.886495ms
Apr 18 07:17:20.519: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064444244s
Apr 18 07:17:22.553: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098569453s
Apr 18 07:17:24.588: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133358027s
Apr 18 07:17:26.622: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167340711s
Apr 18 07:17:28.655: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Running", Reason="", readiness=true. Elapsed: 10.200663602s
Apr 18 07:17:30.688: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Running", Reason="", readiness=true. Elapsed: 12.233788766s
Apr 18 07:17:32.724: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Running", Reason="", readiness=true. Elapsed: 14.269264076s
Apr 18 07:17:34.758: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Running", Reason="", readiness=true. Elapsed: 16.30358576s
Apr 18 07:17:36.791: INFO: Pod "azurefile-volume-tester-h9bnp": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.336558193s
STEP: Saw pod success
Apr 18 07:17:36.791: INFO: Pod "azurefile-volume-tester-h9bnp" 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 07:17:36.856: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-prm77] to have phase Bound
Apr 18 07:17:36.888: INFO: PersistentVolumeClaim pvc-prm77 found and phase=Bound (31.658947ms)
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 07:17:36.986: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-zz992" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 07:17:37.017: INFO: Pod "azurefile-volume-tester-zz992": Phase="Pending", Reason="", readiness=false. Elapsed: 31.64581ms
Apr 18 07:17:39.051: INFO: Pod "azurefile-volume-tester-zz992": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06501494s
Apr 18 07:17:41.085: INFO: Pod "azurefile-volume-tester-zz992": Phase="Pending", Reason="", readiness=false. Elapsed: 4.099410927s
Apr 18 07:17:43.119: INFO: Pod "azurefile-volume-tester-zz992": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133135097s
Apr 18 07:17:45.153: INFO: Pod "azurefile-volume-tester-zz992": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166958153s
Apr 18 07:17:47.186: INFO: Pod "azurefile-volume-tester-zz992": Phase="Running", Reason="", readiness=true. Elapsed: 10.200290203s
Apr 18 07:17:49.219: INFO: Pod "azurefile-volume-tester-zz992": Phase="Running", Reason="", readiness=true. Elapsed: 12.233577613s
Apr 18 07:17:51.253: INFO: Pod "azurefile-volume-tester-zz992": Phase="Running", Reason="", readiness=true. Elapsed: 14.266967156s
Apr 18 07:17:53.286: INFO: Pod "azurefile-volume-tester-zz992": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.300707142s
STEP: Saw pod success
Apr 18 07:17:53.286: INFO: Pod "azurefile-volume-tester-zz992" 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 07:17:53.357: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-w4jsr] to have phase Bound
Apr 18 07:17:53.389: INFO: PersistentVolumeClaim pvc-w4jsr found and phase=Bound (31.674078ms)
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 07:17:53.487: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lwzxt" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 07:17:53.518: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Pending", Reason="", readiness=false. Elapsed: 31.560231ms
Apr 18 07:17:55.552: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06499553s
Apr 18 07:17:57.586: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.099180709s
Apr 18 07:17:59.620: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133215597s
Apr 18 07:18:01.654: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167213888s
Apr 18 07:18:03.690: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Running", Reason="", readiness=true. Elapsed: 10.202998866s
Apr 18 07:18:05.723: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Running", Reason="", readiness=true. Elapsed: 12.236727024s
Apr 18 07:18:07.758: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Running", Reason="", readiness=true. Elapsed: 14.271110009s
Apr 18 07:18:09.791: INFO: Pod "azurefile-volume-tester-lwzxt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.304525882s
STEP: Saw pod success
Apr 18 07:18:09.791: INFO: Pod "azurefile-volume-tester-lwzxt" 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 07:18:09.858: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-clm8z] to have phase Bound
Apr 18 07:18:09.889: INFO: PersistentVolumeClaim pvc-clm8z found and phase=Bound (31.577162ms)
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 07:18:09.985: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vtxhg" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 07:18:10.016: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Pending", Reason="", readiness=false. Elapsed: 31.304277ms
Apr 18 07:18:12.049: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.063882348s
Apr 18 07:18:14.083: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098052681s
Apr 18 07:18:16.117: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.131900498s
Apr 18 07:18:18.151: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.166052656s
Apr 18 07:18:20.185: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Running", Reason="", readiness=true. Elapsed: 10.199914765s
Apr 18 07:18:22.219: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Running", Reason="", readiness=true. Elapsed: 12.233531911s
Apr 18 07:18:24.253: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Running", Reason="", readiness=true. Elapsed: 14.268266859s
Apr 18 07:18:26.292: INFO: Pod "azurefile-volume-tester-vtxhg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.307212232s
STEP: Saw pod success
Apr 18 07:18:26.292: INFO: Pod "azurefile-volume-tester-vtxhg" 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 07:18:26.360: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-wqpf9] to have phase Bound
Apr 18 07:18:26.394: INFO: PersistentVolumeClaim pvc-wqpf9 found and phase=Bound (34.402852ms)
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 07:18:26.492: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-n4k6z" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 07:18:26.523: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Pending", Reason="", readiness=false. Elapsed: 31.544958ms
Apr 18 07:18:28.558: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066187713s
Apr 18 07:18:30.591: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Pending", Reason="", readiness=false. Elapsed: 4.09944125s
Apr 18 07:18:32.625: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132824386s
Apr 18 07:18:34.658: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Pending", Reason="", readiness=false. Elapsed: 8.16646656s
Apr 18 07:18:36.693: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Running", Reason="", readiness=true. Elapsed: 10.201530781s
Apr 18 07:18:38.726: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Running", Reason="", readiness=true. Elapsed: 12.234592267s
Apr 18 07:18:40.759: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Running", Reason="", readiness=true. Elapsed: 14.267760238s
Apr 18 07:18:42.793: INFO: Pod "azurefile-volume-tester-n4k6z": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.30171356s
STEP: Saw pod success
Apr 18 07:18:42.793: INFO: Pod "azurefile-volume-tester-n4k6z" 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 07:18:42.861: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6ktfc] to have phase Bound
Apr 18 07:18:42.892: INFO: PersistentVolumeClaim pvc-6ktfc found and phase=Bound (31.519119ms)
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 07:18:42.989: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-k4spj" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 18 07:18:43.021: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Pending", Reason="", readiness=false. Elapsed: 31.521779ms
Apr 18 07:18:45.054: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06500229s
Apr 18 07:18:47.088: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.098768195s
Apr 18 07:18:49.122: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.133161779s
Apr 18 07:18:51.156: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.167123746s
Apr 18 07:18:53.191: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Running", Reason="", readiness=true. Elapsed: 10.202010141s
Apr 18 07:18:55.225: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Running", Reason="", readiness=true. Elapsed: 12.236072509s
Apr 18 07:18:57.259: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Running", Reason="", readiness=true. Elapsed: 14.270102244s
Apr 18 07:18:59.292: INFO: Pod "azurefile-volume-tester-k4spj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.303150528s
STEP: Saw pod success
Apr 18 07:18:59.292: INFO: Pod "azurefile-volume-tester-k4spj" satisfied condition "Succeeded or Failed"
Apr 18 07:18:59.292: INFO: deleting Pod "azurefile-9103"/"azurefile-volume-tester-k4spj"
Apr 18 07:18:59.344: INFO: Pod azurefile-volume-tester-k4spj has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-k4spj in namespace azurefile-9103
Apr 18 07:18:59.405: INFO: deleting PVC "azurefile-9103"/"pvc-6ktfc"
Apr 18 07:18:59.405: INFO: Deleting PersistentVolumeClaim "pvc-6ktfc"
... skipping 149 lines ...
Apr 18 07:19:07.533: INFO: PersistentVolumeClaim pvc-f2jjg found but phase is Pending instead of Bound.
Apr 18 07:19:09.566: INFO: PersistentVolumeClaim pvc-f2jjg found and phase=Bound (2.065245743s)
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 07:19:09.664: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-jdr25" in namespace "azurefile-8470" to be "Succeeded or Failed"
Apr 18 07:19:09.696: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Pending", Reason="", readiness=false. Elapsed: 32.428311ms
Apr 18 07:19:11.732: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067660878s
Apr 18 07:19:13.766: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Pending", Reason="", readiness=false. Elapsed: 4.102027828s
Apr 18 07:19:15.799: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Pending", Reason="", readiness=false. Elapsed: 6.135434346s
Apr 18 07:19:17.834: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Pending", Reason="", readiness=false. Elapsed: 8.17016903s
Apr 18 07:19:19.868: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204419206s
Apr 18 07:19:21.904: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Running", Reason="", readiness=true. Elapsed: 12.239793241s
Apr 18 07:19:23.938: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Running", Reason="", readiness=true. Elapsed: 14.274318554s
Apr 18 07:19:25.973: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Running", Reason="", readiness=true. Elapsed: 16.308977228s
Apr 18 07:19:28.007: INFO: Pod "azurefile-volume-tester-jdr25": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.34297322s
STEP: Saw pod success
Apr 18 07:19:28.008: INFO: Pod "azurefile-volume-tester-jdr25" satisfied condition "Succeeded or Failed"
Apr 18 07:19:28.008: INFO: deleting Pod "azurefile-8470"/"azurefile-volume-tester-jdr25"
Apr 18 07:19:28.050: INFO: Pod azurefile-volume-tester-jdr25 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-jdr25 in namespace azurefile-8470
Apr 18 07:19:28.095: INFO: deleting PVC "azurefile-8470"/"pvc-f2jjg"
Apr 18 07:19:28.096: INFO: Deleting PersistentVolumeClaim "pvc-f2jjg"
... skipping 33 lines ...
Apr 18 07:19:29.866: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lxjrj] to have phase Bound
Apr 18 07:19:29.898: INFO: PersistentVolumeClaim pvc-lxjrj found and phase=Bound (32.081384ms)
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 07:19:29.999: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-84v7f" in namespace "azurefile-7029" to be "Succeeded or Failed"
Apr 18 07:19:30.032: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Pending", Reason="", readiness=false. Elapsed: 33.042472ms
Apr 18 07:19:32.066: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.066384331s
Apr 18 07:19:34.101: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.101402869s
Apr 18 07:19:36.136: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.137159314s
Apr 18 07:19:38.170: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.171086823s
Apr 18 07:19:40.205: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20603425s
Apr 18 07:19:42.240: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Running", Reason="", readiness=true. Elapsed: 12.240731362s
Apr 18 07:19:44.275: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Running", Reason="", readiness=true. Elapsed: 14.275595651s
Apr 18 07:19:46.310: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Running", Reason="", readiness=true. Elapsed: 16.310773569s
Apr 18 07:19:48.344: INFO: Pod "azurefile-volume-tester-84v7f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.344930283s
STEP: Saw pod success
Apr 18 07:19:48.344: INFO: Pod "azurefile-volume-tester-84v7f" satisfied condition "Succeeded or Failed"
Apr 18 07:19:48.344: INFO: deleting Pod "azurefile-7029"/"azurefile-volume-tester-84v7f"
Apr 18 07:19:48.386: INFO: Pod azurefile-volume-tester-84v7f has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-84v7f in namespace azurefile-7029
Apr 18 07:19:48.449: INFO: deleting PVC "azurefile-7029"/"pvc-lxjrj"
Apr 18 07:19:48.449: INFO: Deleting PersistentVolumeClaim "pvc-lxjrj"
... skipping 86 lines ...
Platform: linux/amd64

Streaming logs below:
I0418 06:56:22.009091       1 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-linux) e2e-test
I0418 06:56:22.009423       1 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 06:56:22.018774       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 06:56:22.019011       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 06:56:22.019034       1 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 06:56:22.019044       1 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0418 06:56:22.019072       1 azure.go:101] read cloud config from file: /etc/kubernetes/azure.json successfully
I0418 06:56:22.020122       1 azure_auth.go:245] Using AzurePublicCloud environment
I0418 06:56:22.020180       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 06:56:22.020254       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 2986 lines ...
Platform: windows/amd64

Streaming logs below:
I0418 06:56:58.431786    5572 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-windows) e2e-test
I0418 06:56:58.447808    5572 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 06:56:58.472713    5572 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 06:56:58.474172    5572 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 06:56:58.474201    5572 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 06:56:58.474230    5572 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0418 06:56:58.474408    5572 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0418 06:56:58.476558    5572 azure_auth.go:245] Using AzurePublicCloud environment
I0418 06:56:58.477069    5572 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 06:56:58.477935    5572 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 53 lines ...
I0418 06:59:13.769061    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:13.770187    5572 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:13.770372    5572 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:13.770950    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:13.770950    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 06:59:13.774338    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
E0418 06:59:20.123360    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 06:59:20.629428    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:20.629428    5572 utils.go:77] GRPC request: {}
I0418 06:59:20.630017    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 06:59:20.632098    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:20.632098    5572 utils.go:77] GRPC request: {}
I0418 06:59:20.632098    5572 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 06:59:20.641786    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:20.642807    5572 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:20.642807    5572 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:20.643596    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:20.643596    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 06:59:20.644204    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
E0418 06:59:23.114748    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 06:59:24.159360    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:24.159360    5572 utils.go:77] GRPC request: {}
I0418 06:59:24.159360    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 06:59:24.161445    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:24.161445    5572 utils.go:77] GRPC request: {}
I0418 06:59:24.161445    5572 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 06:59:24.168331    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:24.168331    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 06:59:24.168978    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:24.204413    5572 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 06:59:24.204413    5572 utils.go:77] GRPC request: {}
I0418 06:59:24.204413    5572 utils.go:83] GRPC response: {"ready":{"value":true}}
E0418 06:59:26.769283    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 06:59:28.799540    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:28.799540    5572 utils.go:77] GRPC request: {}
I0418 06:59:28.799540    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 06:59:28.801964    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:28.801964    5572 utils.go:77] GRPC request: {}
I0418 06:59:28.801964    5572 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 06:59:28.808376    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:28.809054    5572 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:28.809054    5572 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:28.809716    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:28.809716    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 06:59:28.810248    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
E0418 06:59:31.366505    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 06:59:35.448593    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:35.448593    5572 utils.go:77] GRPC request: {}
I0418 06:59:35.448702    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 06:59:35.451776    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:35.451895    5572 utils.go:77] GRPC request: {}
I0418 06:59:35.452102    5572 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 06:59:35.458121    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:35.458649    5572 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:35.458649    5572 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:35.458863    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:35.458863    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 06:59:35.459541    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
E0418 06:59:37.917249    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 06:59:46.026136    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:46.026662    5572 utils.go:77] GRPC request: {}
I0418 06:59:46.026827    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 06:59:46.030772    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 06:59:46.030772    5572 utils.go:77] GRPC request: {}
I0418 06:59:46.030772    5572 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 06:59:46.035177    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:46.035820    5572 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:46.035849    5572 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:46.036314    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 06:59:46.036314    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 06:59:46.037002    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
E0418 06:59:48.242732    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 06:59:54.209270    5572 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 06:59:54.209270    5572 utils.go:77] GRPC request: {}
I0418 06:59:54.209868    5572 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 07:00:04.277462    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 07:00:04.277462    5572 utils.go:77] GRPC request: {}
I0418 07:00:04.278022    5572 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 07:00:04.287368    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 07:00:04.287603    5572 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 07:00:04.287603    5572 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 07:00:04.289233    5572 safe_mounter_windows.go:70] SMBMount: remote path: \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
I0418 07:00:04.289233    5572 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106
I0418 07:00:04.289788    5572 safe_mounter_windows.go:97] begin to mount \\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\globalmount
E0418 07:00:06.562823    5572 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-0q4s14#fd9069829c2bb42628ca524#pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106#) mount "\\\\fd9069829c2bb42628ca524.privatelink.file.core.windows.net\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-0e661aa8-a2a0-4f7a-ba5f-14183293c106\\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 07:00:24.210380    5572 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0418 07:00:24.210380    5572 utils.go:77] GRPC request: {}
I0418 07:00:24.210940    5572 utils.go:83] GRPC response: {"ready":{"value":true}}
I0418 07:00:38.635531    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 07:00:38.635571    5572 utils.go:77] GRPC request: {}
I0418 07:00:38.635651    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
... skipping 1188 lines ...
I0418 07:15:54.892267    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 07:15:54.892267    5572 utils.go:77] GRPC request: {}
I0418 07:15:54.892267    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 07:15:54.895873    5572 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0418 07:15:54.895915    5572 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\07b703aa-2a20-4ba3-99f3-860551ab27a3\\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-qwf9j","csi.storage.k8s.io/pod.namespace":"azurefile-4801","csi.storage.k8s.io/pod.uid":"07b703aa-2a20-4ba3-99f3-860551ab27a3","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"azure-storage-account-f17e239939bcb4a87812841-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-ec6dc5f72484ce5d7a58dae411e341b056bf31221ebd6b67c59144dc3ebdcc27"}
I0418 07:15:54.896073    5572 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-ec6dc5f72484ce5d7a58dae411e341b056bf31221ebd6b67c59144dc3ebdcc27) mount on c:\var\lib\kubelet\pods\07b703aa-2a20-4ba3-99f3-860551ab27a3\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-qwf9j csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:07b703aa-2a20-4ba3-99f3-860551ab27a3 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f17e239939bcb4a87812841-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]
W0418 07:15:54.896153    5572 azurefile.go:546] parsing volumeID(csi-ec6dc5f72484ce5d7a58dae411e341b056bf31221ebd6b67c59144dc3ebdcc27) return with error: error parsing volume id: "csi-ec6dc5f72484ce5d7a58dae411e341b056bf31221ebd6b67c59144dc3ebdcc27", should at least contain two #
I0418 07:15:54.906605    5572 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-4801/secrets/azure-storage-account-f17e239939bcb4a87812841-secret 200 OK in 10 milliseconds
I0418 07:15:54.909332    5572 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\07b703aa-2a20-4ba3-99f3-860551ab27a3\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-ec6dc5f72484ce5d7a58dae411e341b056bf31221ebd6b67c59144dc3ebdcc27) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-qwf9j csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:07b703aa-2a20-4ba3-99f3-860551ab27a3 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f17e239939bcb4a87812841-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\f17e239939bcb4a87812841]) volumeMountGroup()
I0418 07:15:54.909332    5572 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\07b703aa-2a20-4ba3-99f3-860551ab27a3\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 07:15:54.909332    5572 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\07b703aa-2a20-4ba3-99f3-860551ab27a3\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 07:15:54.911629    5572 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\07b703aa-2a20-4ba3-99f3-860551ab27a3\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 07:15:54.912775    5572 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\07b703aa-2a20-4ba3-99f3-860551ab27a3\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 36 lines ...
I0418 07:16:14.760300    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 07:16:14.760300    5572 utils.go:77] GRPC request: {}
I0418 07:16:14.760300    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 07:16:14.762030    5572 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0418 07:16:14.762030    5572 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\592c91be-d9c3-450c-af97-0cb01d9b9a6d\\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-qlkwj","csi.storage.k8s.io/pod.namespace":"azurefile-1166","csi.storage.k8s.io/pod.uid":"592c91be-d9c3-450c-af97-0cb01d9b9a6d","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"smbcreds","server":"20.85.1.211","shareName":"share"},"volume_id":"csi-03886ff9dcf66c30054813865af4d9cff1f2f4345b3f219e5eced158da8323a9"}
I0418 07:16:14.762030    5572 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-03886ff9dcf66c30054813865af4d9cff1f2f4345b3f219e5eced158da8323a9) mount on c:\var\lib\kubelet\pods\592c91be-d9c3-450c-af97-0cb01d9b9a6d\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-qlkwj csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:592c91be-d9c3-450c-af97-0cb01d9b9a6d csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:20.85.1.211 shareName:share storageaccount:]
W0418 07:16:14.762030    5572 azurefile.go:546] parsing volumeID(csi-03886ff9dcf66c30054813865af4d9cff1f2f4345b3f219e5eced158da8323a9) return with error: error parsing volume id: "csi-03886ff9dcf66c30054813865af4d9cff1f2f4345b3f219e5eced158da8323a9", should at least contain two #
I0418 07:16:14.766903    5572 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-1166/secrets/smbcreds 200 OK in 4 milliseconds
I0418 07:16:14.766903    5572 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\592c91be-d9c3-450c-af97-0cb01d9b9a6d\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-03886ff9dcf66c30054813865af4d9cff1f2f4345b3f219e5eced158da8323a9) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-qlkwj csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:592c91be-d9c3-450c-af97-0cb01d9b9a6d csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:20.85.1.211 shareName:share storageaccount:]) mountflags([]) mountOptions([AZURE\USERNAME]) volumeMountGroup()
I0418 07:16:14.766903    5572 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\592c91be-d9c3-450c-af97-0cb01d9b9a6d\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 07:16:14.766903    5572 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\592c91be-d9c3-450c-af97-0cb01d9b9a6d\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 07:16:14.769254    5572 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\592c91be-d9c3-450c-af97-0cb01d9b9a6d\volumes\kubernetes.io~csi\test-volume-1\mount
I0418 07:16:14.769300    5572 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\592c91be-d9c3-450c-af97-0cb01d9b9a6d\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 26 lines ...
I0418 07:16:58.507005    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0418 07:16:58.507005    5572 utils.go:77] GRPC request: {}
I0418 07:16:58.507005    5572 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0418 07:16:58.508181    5572 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume
I0418 07:16:58.508181    5572 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-5320-file.csi.azure.com-preprovsioned-pv-phqjr\\globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_id":"capz-0q4s14#f393723f01cae4df2b963c9#pre-provisioned-readonly##pre-provisioned-readonly"}
I0418 07:16:58.512491    5572 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/default/secrets/azure-storage-account-f393723f01cae4df2b963c9-secret 404 Not Found in 3 milliseconds
I0418 07:16:58.512671    5572 azurefile.go:616] could not get account(f393723f01cae4df2b963c9) key from secret(azure-storage-account-f393723f01cae4df2b963c9-secret), error: could not get secret(azure-storage-account-f393723f01cae4df2b963c9-secret): secrets "azure-storage-account-f393723f01cae4df2b963c9-secret" not found, use cluster identity to get account key instead
(2022-04-18T07:16:58.5145597Z) INFO: REQUEST: POST https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token
User-Agent: Go/go1.18.1 (amd64-windows) go-autorest/adal/v1.0.0
Content-Type: application/x-www-form-urlencoded
(2022-04-18T07:16:58.9945952Z) INFO: RESPONSE: 200 https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token
X-Xss-Protection: 0
Content-Length: 1485
... skipping 707 lines ...
Platform: windows/amd64

Streaming logs below:
I0418 06:56:58.884810    6828 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e gc/go1.18.1 (amd64-windows) e2e-test
I0418 06:56:58.898760    6828 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0418 06:56:58.919789    6828 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 16 milliseconds
W0418 06:56:58.920378    6828 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 06:56:58.920378    6828 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0418 06:56:58.920378    6828 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0418 06:56:58.921100    6828 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0418 06:56:58.923898    6828 azure_auth.go:245] Using AzurePublicCloud environment
I0418 06:56:58.923957    6828 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0418 06:56:58.926280    6828 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 583 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 1495.799 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 (1495.81s)
FAIL
FAIL	sigs.k8s.io/azurefile-csi-driver/test/e2e	1495.871s
FAIL
make: *** [Makefile:85: e2e-test] Error 1
make: Nothing to be done for 'kubectl'.
================ DUMPING LOGS FOR MANAGEMENT CLUSTER ================
Exported logs for cluster "capz" to:
/logs/artifacts/management-cluster
================ DUMPING LOGS FOR WORKLOAD CLUSTER (Linux) ==========
Deploying log-dump-daemonset
... skipping 97 lines ...