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-17 06:41
Elapsed56m30s
Revision6ef34dea3391800ae98f85f6700d7af3463efd40
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] 8m57s

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 | 0xc000b8d7f0>: {
        s: "pod \"azurefile-volume-tester-qzwxk\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +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-17 07:12:16 +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-17 07:12:16 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.7 PodIP:192.168.64.4 PodIPs:[{IP:192.168.64.4}] StartTime:2022-04-17 07:12:16 +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://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a Started:0xc000885f18}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
    }
    pod "azurefile-volume-tester-qzwxk" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +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-17 07:12:16 +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-17 07:12:16 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.7 PodIP:192.168.64.4 PodIPs:[{IP:192.168.64.4}] StartTime:2022-04-17 07:12:16 +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://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a Started:0xc000885f18}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
occurred
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:690
				
				Click to see stdout/stderrfrom junit_01.xml

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

Show 19 Passed Tests
Show 14 Skipped Tests

Error lines from build-log.txt

... skipping 671 lines ...
certificate.cert-manager.io "selfsigned-cert" deleted
# Create secret for AzureClusterIdentity
./hack/create-identity-secret.sh
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
make[2]: Nothing to be done for 'kubectl'.
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Error from server (NotFound): secrets "cluster-identity-secret" not found
secret/cluster-identity-secret created
secret/cluster-identity-secret labeled
# Deploy CAPI
curl --retry 3 -sSL https://github.com/kubernetes-sigs/cluster-api/releases/download/v1.1.2/cluster-api-components.yaml | /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/envsubst-v2.0.0-20210730161058-179042472c46 | kubectl apply -f -
namespace/capi-system created
customresourcedefinition.apiextensions.k8s.io/clusterclasses.cluster.x-k8s.io created
... skipping 180 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11156  100 11156    0     0   122k      0 --:--:-- --:--:-- --:--:--  122k
Downloading https://get.helm.sh/helm-v3.8.2-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull capzci.azurecr.io/azurefile-csi:e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 || make container-all push-manifest
Error response from daemon: manifest for capzci.azurecr.io/azurefile-csi:e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 not found: manifest unknown: manifest tagged by "e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564" is not found
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver'
CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.driverVersion=e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2022-04-17T06:54:50Z -s -w -extldflags '-static'" -mod vendor -o _output/amd64/azurefileplugin.exe ./pkg/azurefileplugin
docker buildx rm container-builder || true
error: no builder "container-builder" found
docker buildx create --use --name=container-builder
container-builder
# enable qemu for arm64 build
# https://github.com/docker/buildx/issues/464#issuecomment-741507760
docker run --privileged --rm tonistiigi/binfmt --uninstall qemu-aarch64
Unable to find image 'tonistiigi/binfmt:latest' locally
... skipping 2473 lines ...
          image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.4.0"
          args:
            - "-csi-address=$(ADDRESS)"
            - "-v=2"
            - "-leader-election"
            - "--leader-election-namespace=kube-system"
            - '-handle-volume-inuse-error=false'
            - '-timeout=120s'
            - '-feature-gates=RecoverVolumeExpansionFailure=true'
          env:
            - name: ADDRESS
              value: /csi/csi.sock
          imagePullPolicy: IfNotPresent
... skipping 148 lines ...
Git Commit: N/A
Go Version: go1.18.1
Platform: linux/amd64

Streaming logs below:
STEP: Building a namespace api object, basename azurefile
W0417 07:10:11.109460   36148 azure.go:78] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
I0417 07:10:11.111236   36148 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0417 07:10:11.111277   36148 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0417 07:10:11.111292   36148 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0417 07:10:11.111298   36148 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0417 07:10:11.111301   36148 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
I0417 07:10:11.111307   36148 driver.go:112] Enabling volume access mode: SINGLE_NODE_WRITER
... skipping 120 lines ...
Apr 17 07:12:14.729: INFO: PersistentVolumeClaim pvc-wp46c found but phase is Pending instead of Bound.
Apr 17 07:12:16.759: INFO: PersistentVolumeClaim pvc-wp46c found and phase=Bound (1m37.418994538s)
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 17 07:12:16.843: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qzwxk" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 17 07:12:16.871: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 27.857399ms
Apr 17 07:12:18.899: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055719168s
Apr 17 07:12:20.928: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.084302341s
Apr 17 07:12:22.958: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.114788908s
Apr 17 07:12:24.987: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.144057924s
Apr 17 07:12:27.015: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.172106238s
... skipping 201 lines ...
Apr 17 07:19:17.055: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 7m0.211791864s
Apr 17 07:19:19.084: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 7m2.241062814s
Apr 17 07:19:21.114: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 7m4.270242195s
Apr 17 07:19:23.143: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 7m6.299911969s
Apr 17 07:19:25.174: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 7m8.33021853s
Apr 17 07:19:27.203: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Pending", Reason="", readiness=false. Elapsed: 7m10.3601485s
Apr 17 07:19:29.233: INFO: Pod "azurefile-volume-tester-qzwxk": Phase="Failed", Reason="", readiness=false. Elapsed: 7m12.390102608s
Apr 17 07:19:29.234: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-qzwxk"
Apr 17 07:19:29.281: INFO: Pod azurefile-volume-tester-qzwxk has the following logs: 
STEP: Deleting pod azurefile-volume-tester-qzwxk in namespace azurefile-2540
Apr 17 07:19:29.318: INFO: deleting PVC "azurefile-2540"/"pvc-wp46c"
Apr 17 07:19:29.318: INFO: Deleting PersistentVolumeClaim "pvc-wp46c"
STEP: waiting for claim's PV "pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" to be deleted
... skipping 6 lines ...
STEP: Collecting events from namespace "azurefile-2540".
STEP: Found 13 events.
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:10:39 +0000 UTC - event for pvc-wp46c: {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 17 07:19:34.549: INFO: At 2022-04-17 07:10:39 +0000 UTC - event for pvc-wp46c: {file.csi.azure.com_capz-hw3kwu-md-0-s5b2t_fad5e90c-aa63-4905-987b-f4fd31c3d02e } Provisioning: External provisioner is provisioning volume for claim "azurefile-2540/pvc-wp46c"
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:12:15 +0000 UTC - event for pvc-wp46c: {file.csi.azure.com_capz-hw3kwu-md-0-s5b2t_fad5e90c-aa63-4905-987b-f4fd31c3d02e } ProvisioningSucceeded: Successfully provisioned volume pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:12:16 +0000 UTC - event for azurefile-volume-tester-qzwxk: {default-scheduler } Scheduled: Successfully assigned azurefile-2540/azurefile-volume-tester-qzwxk to capz-hw3k-g6lbs
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:12:24 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} FailedMount: MountVolume.MountDevice failed for volume "pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" : rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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 17 07:19:34.549: INFO: At 2022-04-17 07:13:13 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:17:27 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m13.8411483s
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:17:27 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Created: Created container volume-tester
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:19:27 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Failed: Error: context deadline exceeded
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:19:28 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} FailedMount: MountVolume.SetUp failed for volume "kube-api-access-2p9v6" : object "azurefile-2540"/"kube-root-ca.crt" not registered
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:19:28 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:19:32 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Started: Started container volume-tester
Apr 17 07:19:34.549: INFO: At 2022-04-17 07:19:33 +0000 UTC - event for azurefile-volume-tester-qzwxk: {kubelet capz-hw3k-g6lbs} Killing: Stopping container volume-tester
Apr 17 07:19:34.577: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 17 07:19:34.577: INFO: 
Apr 17 07:19:34.614: INFO: 
... skipping 115 lines ...
• Failure [537.294 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 | 0xc000b8d7f0>: {
          s: "pod \"azurefile-volume-tester-qzwxk\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +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-17 07:12:16 +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-17 07:12:16 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.7 PodIP:192.168.64.4 PodIPs:[{IP:192.168.64.4}] StartTime:2022-04-17 07:12:16 +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://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a Started:0xc000885f18}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
      }
      pod "azurefile-volume-tester-qzwxk" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-04-17 07:12:16 +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-17 07:12:16 +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-17 07:12:16 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.7 PodIP:192.168.64.4 PodIPs:[{IP:192.168.64.4}] StartTime:2022-04-17 07:12:16 +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://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a,}} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2022 ImageID:mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e ContainerID:containerd://8a1b4e221ce200dfaade518931d7e99a5fc9cae8695661dd48295be3f8c8805a Started:0xc000885f18}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:690
------------------------------
Dynamic Provisioning 
  should create a pod with volume mount subpath [file.csi.azure.com] [Windows]
... skipping 31 lines ...
Apr 17 07:20:05.245: INFO: PersistentVolumeClaim pvc-8cskp found but phase is Pending instead of Bound.
Apr 17 07:20:07.275: INFO: PersistentVolumeClaim pvc-8cskp found and phase=Bound (30.464953265s)
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 17 07:20:07.363: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-gf52f" in namespace "azurefile-4728" to be "Succeeded or Failed"
Apr 17 07:20:07.391: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 27.735789ms
Apr 17 07:20:09.420: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056434547s
Apr 17 07:20:11.450: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086613686s
Apr 17 07:20:13.480: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.116448865s
Apr 17 07:20:15.509: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.145551358s
Apr 17 07:20:17.539: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.175213s
Apr 17 07:20:19.569: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 12.205313914s
Apr 17 07:20:21.598: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Pending", Reason="", readiness=false. Elapsed: 14.234797521s
Apr 17 07:20:23.628: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Running", Reason="", readiness=true. Elapsed: 16.264440794s
Apr 17 07:20:25.657: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Running", Reason="", readiness=true. Elapsed: 18.293851252s
Apr 17 07:20:27.688: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Running", Reason="", readiness=true. Elapsed: 20.324967286s
Apr 17 07:20:29.717: INFO: Pod "azurefile-volume-tester-gf52f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.353931568s
STEP: Saw pod success
Apr 17 07:20:29.718: INFO: Pod "azurefile-volume-tester-gf52f" satisfied condition "Succeeded or Failed"
Apr 17 07:20:29.718: INFO: deleting Pod "azurefile-4728"/"azurefile-volume-tester-gf52f"
Apr 17 07:20:29.755: INFO: Pod azurefile-volume-tester-gf52f has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-gf52f in namespace azurefile-4728
Apr 17 07:20:29.789: INFO: deleting PVC "azurefile-4728"/"pvc-8cskp"
Apr 17 07:20:29.789: INFO: Deleting PersistentVolumeClaim "pvc-8cskp"
... skipping 116 lines ...
Apr 17 07:21:33.531: INFO: PersistentVolumeClaim pvc-m29dv found but phase is Pending instead of Bound.
Apr 17 07:21:35.560: INFO: PersistentVolumeClaim pvc-m29dv found and phase=Bound (20.313260829s)
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 17 07:21:35.645: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qcnfl" in namespace "azurefile-2790" to be "Error status code"
Apr 17 07:21:35.672: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Pending", Reason="", readiness=false. Elapsed: 27.579633ms
Apr 17 07:21:37.702: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056917708s
Apr 17 07:21:39.731: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086535777s
Apr 17 07:21:41.761: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.116609369s
Apr 17 07:21:43.790: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.145402571s
Apr 17 07:21:45.820: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Pending", Reason="", readiness=false. Elapsed: 10.175099273s
Apr 17 07:21:47.849: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Running", Reason="", readiness=true. Elapsed: 12.204000169s
Apr 17 07:21:49.878: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Running", Reason="", readiness=true. Elapsed: 14.23359506s
Apr 17 07:21:51.908: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Running", Reason="", readiness=true. Elapsed: 16.262958094s
Apr 17 07:21:53.937: INFO: Pod "azurefile-volume-tester-qcnfl": Phase="Failed", Reason="", readiness=false. Elapsed: 18.292151348s
STEP: Saw pod failure
Apr 17 07:21:53.937: INFO: Pod "azurefile-volume-tester-qcnfl" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 17 07:21:53.977: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-qcnfl"
Apr 17 07:21:54.012: INFO: Pod azurefile-volume-tester-qcnfl 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 17 07:23:10.554: INFO: PersistentVolumeClaim pvc-q2nhw found but phase is Pending instead of Bound.
Apr 17 07:23:12.584: INFO: PersistentVolumeClaim pvc-q2nhw found and phase=Bound (2.065524983s)
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 17 07:23:12.673: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-75wg7" in namespace "azurefile-4538" to be "Succeeded or Failed"
Apr 17 07:23:12.701: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 27.265012ms
Apr 17 07:23:14.729: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055292273s
Apr 17 07:23:16.757: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08368721s
Apr 17 07:23:18.786: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.112233836s
Apr 17 07:23:20.815: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.141689752s
Apr 17 07:23:22.845: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 10.17168953s
Apr 17 07:23:24.874: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Pending", Reason="", readiness=false. Elapsed: 12.200555603s
Apr 17 07:23:26.905: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Running", Reason="", readiness=true. Elapsed: 14.232068969s
Apr 17 07:23:28.935: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Running", Reason="", readiness=true. Elapsed: 16.261389854s
Apr 17 07:23:30.964: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Running", Reason="", readiness=true. Elapsed: 18.290975883s
Apr 17 07:23:32.993: INFO: Pod "azurefile-volume-tester-75wg7": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.319933599s
STEP: Saw pod success
Apr 17 07:23:32.993: INFO: Pod "azurefile-volume-tester-75wg7" 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 17 07:24:03.340: INFO: deleting Pod "azurefile-4538"/"azurefile-volume-tester-75wg7"
... skipping 303 lines ...
Apr 17 07:24:24.397: INFO: PersistentVolumeClaim pvc-m2xqh found but phase is Pending instead of Bound.
Apr 17 07:24:26.426: INFO: PersistentVolumeClaim pvc-m2xqh found and phase=Bound (2.056703977s)
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 17 07:24:26.511: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-t5922" in namespace "azurefile-7726" to be "Succeeded or Failed"
Apr 17 07:24:26.539: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 28.155427ms
Apr 17 07:24:28.569: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057738677s
Apr 17 07:24:30.599: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 4.088131884s
Apr 17 07:24:32.629: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 6.117924724s
Apr 17 07:24:34.659: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 8.147875178s
Apr 17 07:24:36.688: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 10.17761478s
Apr 17 07:24:38.720: INFO: Pod "azurefile-volume-tester-t5922": Phase="Pending", Reason="", readiness=false. Elapsed: 12.208688241s
Apr 17 07:24:40.749: INFO: Pod "azurefile-volume-tester-t5922": Phase="Running", Reason="", readiness=true. Elapsed: 14.237827029s
Apr 17 07:24:42.780: INFO: Pod "azurefile-volume-tester-t5922": Phase="Running", Reason="", readiness=true. Elapsed: 16.268650062s
Apr 17 07:24:44.809: INFO: Pod "azurefile-volume-tester-t5922": Phase="Running", Reason="", readiness=true. Elapsed: 18.298130126s
Apr 17 07:24:46.839: INFO: Pod "azurefile-volume-tester-t5922": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.327826777s
STEP: Saw pod success
Apr 17 07:24:46.839: INFO: Pod "azurefile-volume-tester-t5922" satisfied condition "Succeeded or Failed"
Apr 17 07:24:46.839: INFO: deleting Pod "azurefile-7726"/"azurefile-volume-tester-t5922"
Apr 17 07:24:47.150: INFO: Pod azurefile-volume-tester-t5922 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-t5922 in namespace azurefile-7726
Apr 17 07:24:47.185: INFO: deleting PVC "azurefile-7726"/"pvc-m2xqh"
Apr 17 07:24:47.185: INFO: Deleting PersistentVolumeClaim "pvc-m2xqh"
... skipping 96 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/17 07:25:19 Check successfully
Apr 17 07:25:19.479: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/17 07:25:19 run script: test/utils/get_storage_account_secret_name.sh
2022/04/17 07:25:19 got output: azure-storage-account-f76f2647d622d47d1bc2366-secret
, error: <nil>
2022/04/17 07:25:19 got storage account secret name: azure-storage-account-f76f2647d622d47d1bc2366-secret
STEP: setting up the StorageClass
STEP: creating a StorageClass 
STEP: setting up the PVC and PV
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 17 07:25:19.749: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-wff64] to have phase Bound
Apr 17 07:25:19.777: INFO: PersistentVolumeClaim pvc-wff64 found but phase is Pending instead of Bound.
Apr 17 07:25:21.806: INFO: PersistentVolumeClaim pvc-wff64 found and phase=Bound (2.056592408s)
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 17 07:25:21.891: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-zdqp7" in namespace "azurefile-1387" to be "Succeeded or Failed"
Apr 17 07:25:21.918: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Pending", Reason="", readiness=false. Elapsed: 27.665507ms
Apr 17 07:25:23.948: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.05702505s
Apr 17 07:25:25.978: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.087433585s
Apr 17 07:25:28.007: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.11677687s
Apr 17 07:25:30.036: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.145665075s
Apr 17 07:25:32.065: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Running", Reason="", readiness=true. Elapsed: 10.174501762s
Apr 17 07:25:34.095: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Running", Reason="", readiness=true. Elapsed: 12.20459056s
Apr 17 07:25:36.124: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Running", Reason="", readiness=true. Elapsed: 14.233456639s
Apr 17 07:25:38.155: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Running", Reason="", readiness=true. Elapsed: 16.26396048s
Apr 17 07:25:40.184: INFO: Pod "azurefile-volume-tester-zdqp7": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.293514356s
STEP: Saw pod success
Apr 17 07:25:40.184: INFO: Pod "azurefile-volume-tester-zdqp7" satisfied condition "Succeeded or Failed"
Apr 17 07:25:40.184: INFO: deleting Pod "azurefile-1387"/"azurefile-volume-tester-zdqp7"
Apr 17 07:25:40.220: INFO: Pod azurefile-volume-tester-zdqp7 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-zdqp7 in namespace azurefile-1387
Apr 17 07:25:40.260: INFO: deleting PVC "azurefile-1387"/"pvc-wff64"
Apr 17 07:25:40.260: INFO: Deleting PersistentVolumeClaim "pvc-wff64"
... skipping 44 lines ...
Apr 17 07:26:04.374: INFO: PersistentVolumeClaim pvc-kllh7 found but phase is Pending instead of Bound.
Apr 17 07:26:06.404: INFO: PersistentVolumeClaim pvc-kllh7 found and phase=Bound (20.318983512s)
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 17 07:26:06.489: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7vrsw" in namespace "azurefile-4547" to be "Succeeded or Failed"
Apr 17 07:26:06.520: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Pending", Reason="", readiness=false. Elapsed: 30.340832ms
Apr 17 07:26:08.548: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.059049183s
Apr 17 07:26:10.577: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08798468s
Apr 17 07:26:12.608: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.118313566s
Apr 17 07:26:14.637: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.148090035s
Apr 17 07:26:16.667: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Running", Reason="", readiness=true. Elapsed: 10.177969283s
Apr 17 07:26:18.697: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Running", Reason="", readiness=true. Elapsed: 12.207638515s
Apr 17 07:26:20.726: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Running", Reason="", readiness=true. Elapsed: 14.236500697s
Apr 17 07:26:22.756: INFO: Pod "azurefile-volume-tester-7vrsw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.266389903s
STEP: Saw pod success
Apr 17 07:26:22.756: INFO: Pod "azurefile-volume-tester-7vrsw" satisfied condition "Succeeded or Failed"
Apr 17 07:26:22.756: INFO: deleting Pod "azurefile-4547"/"azurefile-volume-tester-7vrsw"
Apr 17 07:26:22.796: INFO: Pod azurefile-volume-tester-7vrsw has the following logs: hello world

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

STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 17 07:27:51.860: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vthsh" in namespace "azurefile-4801" to be "Succeeded or Failed"
Apr 17 07:27:51.893: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Pending", Reason="", readiness=false. Elapsed: 33.401362ms
Apr 17 07:27:53.923: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.062819119s
Apr 17 07:27:55.952: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.092461599s
Apr 17 07:27:57.983: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.122622377s
Apr 17 07:28:00.012: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.152220038s
Apr 17 07:28:02.041: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Running", Reason="", readiness=true. Elapsed: 10.181555524s
Apr 17 07:28:04.071: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Running", Reason="", readiness=true. Elapsed: 12.210860413s
Apr 17 07:28:06.101: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Running", Reason="", readiness=true. Elapsed: 14.241103596s
Apr 17 07:28:08.131: INFO: Pod "azurefile-volume-tester-vthsh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.270806901s
STEP: Saw pod success
Apr 17 07:28:08.131: INFO: Pod "azurefile-volume-tester-vthsh" satisfied condition "Succeeded or Failed"
Apr 17 07:28:08.131: INFO: deleting Pod "azurefile-4801"/"azurefile-volume-tester-vthsh"
Apr 17 07:28:08.168: INFO: Pod azurefile-volume-tester-vthsh has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-vthsh in namespace azurefile-4801
Apr 17 07:28:08.206: 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/17 07:28:09 Check successfully
Apr 17 07:28:09.257: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: creating secret smbcreds in namespace azurefile-1166
2022/04/17 07:28:09 run script: test/utils/get_smb_svc_public_ip.sh
2022/04/17 07:28:09 got output: 52.226.200.247
, error: <nil>
2022/04/17 07:28:09 use server on Windows: 52.226.200.247
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 17 07:28:09.545: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-njmqg" in namespace "azurefile-1166" to be "Succeeded or Failed"
Apr 17 07:28:09.580: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Pending", Reason="", readiness=false. Elapsed: 35.403729ms
Apr 17 07:28:11.610: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064722682s
Apr 17 07:28:13.640: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.094959184s
Apr 17 07:28:15.670: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.125095644s
Apr 17 07:28:17.699: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.154431251s
Apr 17 07:28:19.729: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.184030183s
Apr 17 07:28:21.759: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Running", Reason="", readiness=true. Elapsed: 12.213508749s
Apr 17 07:28:23.788: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Running", Reason="", readiness=true. Elapsed: 14.243223593s
Apr 17 07:28:25.818: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Running", Reason="", readiness=true. Elapsed: 16.272581491s
Apr 17 07:28:27.849: INFO: Pod "azurefile-volume-tester-njmqg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.303909132s
STEP: Saw pod success
Apr 17 07:28:27.849: INFO: Pod "azurefile-volume-tester-njmqg" satisfied condition "Succeeded or Failed"
Apr 17 07:28:27.849: INFO: deleting Pod "azurefile-1166"/"azurefile-volume-tester-njmqg"
Apr 17 07:28:27.886: INFO: Pod azurefile-volume-tester-njmqg has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-njmqg in namespace azurefile-1166
Apr 17 07:28:27.921: INFO: deleting Secret smbcreds
Apr 17 07:28:27.950: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
... skipping 132 lines ...
Apr 17 07:28:31.387: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-zn66r] to have phase Bound
Apr 17 07:28:31.414: INFO: PersistentVolumeClaim pvc-zn66r found and phase=Bound (27.09285ms)
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 17 07:28:31.501: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-jdm2g" in namespace "azurefile-5320" to be "Error status code"
Apr 17 07:28:31.529: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Pending", Reason="", readiness=false. Elapsed: 27.934201ms
Apr 17 07:28:33.560: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.058751296s
Apr 17 07:28:35.589: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.088323671s
Apr 17 07:28:37.619: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.117537261s
Apr 17 07:28:39.650: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.149239007s
Apr 17 07:28:41.681: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.179856051s
Apr 17 07:28:43.713: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Running", Reason="", readiness=true. Elapsed: 12.211861209s
Apr 17 07:28:45.742: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Running", Reason="", readiness=true. Elapsed: 14.240556881s
Apr 17 07:28:47.771: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Running", Reason="", readiness=true. Elapsed: 16.269470998s
Apr 17 07:28:49.800: INFO: Pod "azurefile-volume-tester-jdm2g": Phase="Failed", Reason="", readiness=false. Elapsed: 18.299401805s
STEP: Saw pod failure
Apr 17 07:28:49.800: INFO: Pod "azurefile-volume-tester-jdm2g" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 17 07:28:49.842: INFO: deleting Pod "azurefile-5320"/"azurefile-volume-tester-jdm2g"
Apr 17 07:28:49.874: INFO: Pod azurefile-volume-tester-jdm2g 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 17 07:28:51.418: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-5nkq5] to have phase Bound
Apr 17 07:28:51.446: INFO: PersistentVolumeClaim pvc-5nkq5 found and phase=Bound (27.614182ms)
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 17 07:28:51.530: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8xzk8" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 17 07:28:51.558: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Pending", Reason="", readiness=false. Elapsed: 27.944851ms
Apr 17 07:28:53.587: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056762048s
Apr 17 07:28:55.617: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086906187s
Apr 17 07:28:57.647: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.116506783s
Apr 17 07:28:59.676: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.145959678s
Apr 17 07:29:01.706: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Running", Reason="", readiness=true. Elapsed: 10.176324572s
Apr 17 07:29:03.736: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Running", Reason="", readiness=true. Elapsed: 12.205726788s
Apr 17 07:29:05.765: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Running", Reason="", readiness=true. Elapsed: 14.234881858s
Apr 17 07:29:07.795: INFO: Pod "azurefile-volume-tester-8xzk8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.264694124s
STEP: Saw pod success
Apr 17 07:29:07.795: INFO: Pod "azurefile-volume-tester-8xzk8" 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 17 07:29:07.852: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-rj6wm] to have phase Bound
Apr 17 07:29:07.879: INFO: PersistentVolumeClaim pvc-rj6wm found and phase=Bound (27.3581ms)
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 17 07:29:07.966: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-pbj7k" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 17 07:29:07.994: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Pending", Reason="", readiness=false. Elapsed: 27.573147ms
Apr 17 07:29:10.023: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057005797s
Apr 17 07:29:12.052: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086228998s
Apr 17 07:29:14.081: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.115236003s
Apr 17 07:29:16.110: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.144050281s
Apr 17 07:29:18.139: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Running", Reason="", readiness=true. Elapsed: 10.173229527s
Apr 17 07:29:20.169: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Running", Reason="", readiness=true. Elapsed: 12.203272335s
Apr 17 07:29:22.199: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Running", Reason="", readiness=true. Elapsed: 14.232606121s
Apr 17 07:29:24.228: INFO: Pod "azurefile-volume-tester-pbj7k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.26219305s
STEP: Saw pod success
Apr 17 07:29:24.228: INFO: Pod "azurefile-volume-tester-pbj7k" 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 17 07:29:24.289: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-dkdnf] to have phase Bound
Apr 17 07:29:24.316: INFO: PersistentVolumeClaim pvc-dkdnf found and phase=Bound (27.29518ms)
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 17 07:29:24.406: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7khc4" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 17 07:29:24.434: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Pending", Reason="", readiness=false. Elapsed: 27.774705ms
Apr 17 07:29:26.462: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055796962s
Apr 17 07:29:28.492: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086013219s
Apr 17 07:29:30.521: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.11533788s
Apr 17 07:29:32.552: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.146300183s
Apr 17 07:29:34.582: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Running", Reason="", readiness=true. Elapsed: 10.175531126s
Apr 17 07:29:36.611: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Running", Reason="", readiness=true. Elapsed: 12.205072897s
Apr 17 07:29:38.641: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Running", Reason="", readiness=true. Elapsed: 14.235034749s
Apr 17 07:29:40.671: INFO: Pod "azurefile-volume-tester-7khc4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.265122933s
STEP: Saw pod success
Apr 17 07:29:40.671: INFO: Pod "azurefile-volume-tester-7khc4" 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 17 07:29:40.728: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lbz5t] to have phase Bound
Apr 17 07:29:40.756: INFO: PersistentVolumeClaim pvc-lbz5t found and phase=Bound (27.474432ms)
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 17 07:29:40.841: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8mstc" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 17 07:29:40.871: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Pending", Reason="", readiness=false. Elapsed: 30.589494ms
Apr 17 07:29:42.901: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.060477769s
Apr 17 07:29:44.931: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.090538267s
Apr 17 07:29:46.961: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.120879405s
Apr 17 07:29:48.990: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.149686437s
Apr 17 07:29:51.026: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Running", Reason="", readiness=true. Elapsed: 10.185349173s
Apr 17 07:29:53.055: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Running", Reason="", readiness=true. Elapsed: 12.214798654s
Apr 17 07:29:55.086: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Running", Reason="", readiness=true. Elapsed: 14.245197175s
Apr 17 07:29:57.116: INFO: Pod "azurefile-volume-tester-8mstc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.275347092s
STEP: Saw pod success
Apr 17 07:29:57.116: INFO: Pod "azurefile-volume-tester-8mstc" 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 17 07:29:57.179: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-c79fd] to have phase Bound
Apr 17 07:29:57.214: INFO: PersistentVolumeClaim pvc-c79fd found and phase=Bound (35.054227ms)
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 17 07:29:57.302: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-jlmbg" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 17 07:29:57.329: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Pending", Reason="", readiness=false. Elapsed: 27.515883ms
Apr 17 07:29:59.358: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055940815s
Apr 17 07:30:01.388: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086109472s
Apr 17 07:30:03.417: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.115666321s
Apr 17 07:30:05.447: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.145177166s
Apr 17 07:30:07.478: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Running", Reason="", readiness=true. Elapsed: 10.175973293s
Apr 17 07:30:09.507: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Running", Reason="", readiness=true. Elapsed: 12.205414073s
Apr 17 07:30:11.536: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Running", Reason="", readiness=true. Elapsed: 14.234548876s
Apr 17 07:30:13.565: INFO: Pod "azurefile-volume-tester-jlmbg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.263168903s
STEP: Saw pod success
Apr 17 07:30:13.565: INFO: Pod "azurefile-volume-tester-jlmbg" 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 17 07:30:13.623: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-4fkp6] to have phase Bound
Apr 17 07:30:13.650: INFO: PersistentVolumeClaim pvc-4fkp6 found and phase=Bound (27.340814ms)
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 17 07:30:13.735: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8w2xj" in namespace "azurefile-9103" to be "Succeeded or Failed"
Apr 17 07:30:13.762: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Pending", Reason="", readiness=false. Elapsed: 27.330108ms
Apr 17 07:30:15.792: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056526171s
Apr 17 07:30:17.822: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086648321s
Apr 17 07:30:19.855: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.120213966s
Apr 17 07:30:21.885: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.149824623s
Apr 17 07:30:23.915: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Running", Reason="", readiness=true. Elapsed: 10.179713798s
Apr 17 07:30:25.944: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Running", Reason="", readiness=true. Elapsed: 12.209194175s
Apr 17 07:30:27.974: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Running", Reason="", readiness=true. Elapsed: 14.239012227s
Apr 17 07:30:30.004: INFO: Pod "azurefile-volume-tester-8w2xj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.269131415s
STEP: Saw pod success
Apr 17 07:30:30.004: INFO: Pod "azurefile-volume-tester-8w2xj" satisfied condition "Succeeded or Failed"
Apr 17 07:30:30.004: INFO: deleting Pod "azurefile-9103"/"azurefile-volume-tester-8w2xj"
Apr 17 07:30:30.055: INFO: Pod azurefile-volume-tester-8w2xj has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-8w2xj in namespace azurefile-9103
Apr 17 07:30:30.091: INFO: deleting PVC "azurefile-9103"/"pvc-4fkp6"
Apr 17 07:30:30.091: INFO: Deleting PersistentVolumeClaim "pvc-4fkp6"
... skipping 143 lines ...
Apr 17 07:30:35.071: INFO: PersistentVolumeClaim pvc-tlbbw found but phase is Pending instead of Bound.
Apr 17 07:30:37.100: INFO: PersistentVolumeClaim pvc-tlbbw found and phase=Bound (2.056460234s)
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 17 07:30:37.186: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-8rbxv" in namespace "azurefile-8470" to be "Succeeded or Failed"
Apr 17 07:30:37.213: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Pending", Reason="", readiness=false. Elapsed: 27.361293ms
Apr 17 07:30:39.242: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056144705s
Apr 17 07:30:41.272: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08596624s
Apr 17 07:30:43.301: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.115330246s
Apr 17 07:30:45.332: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.146001271s
Apr 17 07:30:47.363: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.177085224s
Apr 17 07:30:49.392: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Running", Reason="", readiness=true. Elapsed: 12.206441117s
Apr 17 07:30:51.422: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Running", Reason="", readiness=true. Elapsed: 14.236586183s
Apr 17 07:30:53.453: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Running", Reason="", readiness=true. Elapsed: 16.267028458s
Apr 17 07:30:55.483: INFO: Pod "azurefile-volume-tester-8rbxv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.296692612s
STEP: Saw pod success
Apr 17 07:30:55.483: INFO: Pod "azurefile-volume-tester-8rbxv" satisfied condition "Succeeded or Failed"
Apr 17 07:30:55.483: INFO: deleting Pod "azurefile-8470"/"azurefile-volume-tester-8rbxv"
Apr 17 07:30:55.520: INFO: Pod azurefile-volume-tester-8rbxv has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-8rbxv in namespace azurefile-8470
Apr 17 07:30:55.565: INFO: deleting PVC "azurefile-8470"/"pvc-tlbbw"
Apr 17 07:30:55.565: INFO: Deleting PersistentVolumeClaim "pvc-tlbbw"
... skipping 33 lines ...
Apr 17 07:30:57.009: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-gvqj9] to have phase Bound
Apr 17 07:30:57.037: INFO: PersistentVolumeClaim pvc-gvqj9 found and phase=Bound (27.459954ms)
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 17 07:30:57.122: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-wnmmt" in namespace "azurefile-7029" to be "Succeeded or Failed"
Apr 17 07:30:57.150: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Pending", Reason="", readiness=false. Elapsed: 28.186645ms
Apr 17 07:30:59.179: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057034578s
Apr 17 07:31:01.208: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086355315s
Apr 17 07:31:03.239: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.117428463s
Apr 17 07:31:05.270: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.148171716s
Apr 17 07:31:07.300: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.178514868s
Apr 17 07:31:09.329: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Running", Reason="", readiness=true. Elapsed: 12.207627743s
Apr 17 07:31:11.359: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Running", Reason="", readiness=true. Elapsed: 14.237582664s
Apr 17 07:31:13.389: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Running", Reason="", readiness=true. Elapsed: 16.267340307s
Apr 17 07:31:15.419: INFO: Pod "azurefile-volume-tester-wnmmt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.297439401s
STEP: Saw pod success
Apr 17 07:31:15.419: INFO: Pod "azurefile-volume-tester-wnmmt" satisfied condition "Succeeded or Failed"
Apr 17 07:31:15.419: INFO: deleting Pod "azurefile-7029"/"azurefile-volume-tester-wnmmt"
Apr 17 07:31:15.459: INFO: Pod azurefile-volume-tester-wnmmt has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-wnmmt in namespace azurefile-7029
Apr 17 07:31:15.497: INFO: deleting PVC "azurefile-7029"/"pvc-gvqj9"
Apr 17 07:31:15.497: INFO: Deleting PersistentVolumeClaim "pvc-gvqj9"
... skipping 86 lines ...
Platform: linux/amd64

Streaming logs below:
I0417 07:09:21.328918       1 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 gc/go1.18.1 (amd64-linux) e2e-test
I0417 07:09:21.329274       1 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0417 07:09:21.343652       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 14 milliseconds
W0417 07:09:21.343902       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
I0417 07:09:21.343919       1 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0417 07:09:21.343929       1 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0417 07:09:21.343969       1 azure.go:101] read cloud config from file: /etc/kubernetes/azure.json successfully
I0417 07:09:21.344442       1 azure_auth.go:245] Using AzurePublicCloud environment
I0417 07:09:21.344490       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0417 07:09:21.344554       1 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 2917 lines ...
Platform: windows/amd64

Streaming logs below:
I0417 07:10:07.671988    7108 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 gc/go1.18.1 (amd64-windows) e2e-test
I0417 07:10:07.694610    7108 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0417 07:10:07.699443    7108 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider  in 2 milliseconds
W0417 07:10:07.700274    7108 azure.go:78] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: Get "https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider": dial tcp 10.96.0.1:443: connectex: An attempt was made to access a socket in a way forbidden by its access permissions.
I0417 07:10:07.700994    7108 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0417 07:10:07.700994    7108 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0417 07:10:07.700994    7108 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0417 07:10:07.708701    7108 azure_auth.go:245] Using AzurePublicCloud environment
I0417 07:10:07.709361    7108 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0417 07:10:07.710478    7108 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 53 lines ...
I0417 07:12:17.129290    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:17.131094    7108 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:17.131094    7108 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:17.131770    7108 safe_mounter_windows.go:70] SMBMount: remote path: \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:17.131770    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
I0417 07:12:17.132569    7108 safe_mounter_windows.go:97] begin to mount \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
E0417 07:12:24.202654    7108 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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
I0417 07:12:24.808094    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:24.808784    7108 utils.go:77] GRPC request: {}
I0417 07:12:24.808904    7108 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0417 07:12:24.815964    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:24.815964    7108 utils.go:77] GRPC request: {}
I0417 07:12:24.815964    7108 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 ...
I0417 07:12:24.820779    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:24.821614    7108 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:24.821614    7108 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:24.822133    7108 safe_mounter_windows.go:70] SMBMount: remote path: \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:24.822164    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
I0417 07:12:24.822164    7108 safe_mounter_windows.go:97] begin to mount \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
E0417 07:12:27.142834    7108 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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
I0417 07:12:28.215372    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:28.215372    7108 utils.go:77] GRPC request: {}
I0417 07:12:28.215372    7108 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0417 07:12:28.218176    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:28.218176    7108 utils.go:77] GRPC request: {}
I0417 07:12:28.218266    7108 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 ...
I0417 07:12:28.225599    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:28.225995    7108 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:28.225995    7108 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:28.226581    7108 safe_mounter_windows.go:70] SMBMount: remote path: \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:28.226581    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
I0417 07:12:28.227414    7108 safe_mounter_windows.go:97] begin to mount \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
E0417 07:12:30.595328    7108 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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
I0417 07:12:32.676275    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:32.676275    7108 utils.go:77] GRPC request: {}
I0417 07:12:32.676275    7108 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0417 07:12:32.679236    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:32.679236    7108 utils.go:77] GRPC request: {}
I0417 07:12:32.679236    7108 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 ...
I0417 07:12:32.686022    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:32.686482    7108 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:32.686482    7108 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:32.687342    7108 safe_mounter_windows.go:70] SMBMount: remote path: \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:32.687342    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
I0417 07:12:32.687342    7108 safe_mounter_windows.go:97] begin to mount \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
E0417 07:12:35.066020    7108 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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
I0417 07:12:35.499607    7108 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0417 07:12:35.499607    7108 utils.go:77] GRPC request: {}
I0417 07:12:35.499607    7108 utils.go:83] GRPC response: {"ready":{"value":true}}
I0417 07:12:39.094213    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:39.094247    7108 utils.go:77] GRPC request: {}
I0417 07:12:39.094247    7108 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 ...
I0417 07:12:39.103822    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:39.104545    7108 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:39.104545    7108 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:39.105511    7108 safe_mounter_windows.go:70] SMBMount: remote path: \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:39.105534    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
I0417 07:12:39.105738    7108 safe_mounter_windows.go:97] begin to mount \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
E0417 07:12:41.373980    7108 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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
I0417 07:12:49.432159    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:49.432159    7108 utils.go:77] GRPC request: {}
I0417 07:12:49.432159    7108 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0417 07:12:49.434601    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:12:49.434601    7108 utils.go:77] GRPC request: {}
I0417 07:12:49.434601    7108 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 ...
I0417 07:12:49.439591    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:49.440074    7108 azure_common_windows.go:73] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:49.440101    7108 safe_mounter_windows.go:133] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:49.440354    7108 safe_mounter_windows.go:70] SMBMount: remote path: \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 local path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
I0417 07:12:49.440354    7108 safe_mounter_windows.go:220] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3
I0417 07:12:49.441037    7108 safe_mounter_windows.go:97] begin to mount \\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3 on c:\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\globalmount
E0417 07:12:51.688757    7108 utils.go:81] GRPC error: rpc error: code = Internal desc = volume(capz-hw3kwu#fedf9d94b13a54e409b27ba#pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3#) mount "\\\\fedf9d94b13a54e409b27ba.privatelink.file.core.windows.net\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-84516bc7-16ed-4a4a-9797-beaa8c3510b3\\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
I0417 07:13:05.495161    7108 utils.go:76] GRPC call: /csi.v1.Identity/Probe
I0417 07:13:05.495161    7108 utils.go:77] GRPC request: {}
I0417 07:13:05.496020    7108 utils.go:83] GRPC response: {"ready":{"value":true}}
I0417 07:13:07.779562    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:13:07.779562    7108 utils.go:77] GRPC request: {}
I0417 07:13:07.779562    7108 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 ...
I0417 07:27:52.141523    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:27:52.141523    7108 utils.go:77] GRPC request: {}
I0417 07:27:52.141523    7108 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0417 07:27:52.142711    7108 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0417 07:27:52.142711    7108 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\3be97881-5212-4fe3-b85c-afeb526fc5a5\\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-vthsh","csi.storage.k8s.io/pod.namespace":"azurefile-4801","csi.storage.k8s.io/pod.uid":"3be97881-5212-4fe3-b85c-afeb526fc5a5","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"azure-storage-account-f76f2647d622d47d1bc2366-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-1d0f8ae8da18c5a50a65db3710545ed3eee501241268c97a9a02ef2b26f8fe60"}
I0417 07:27:52.142711    7108 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-1d0f8ae8da18c5a50a65db3710545ed3eee501241268c97a9a02ef2b26f8fe60) mount on c:\var\lib\kubelet\pods\3be97881-5212-4fe3-b85c-afeb526fc5a5\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-vthsh csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:3be97881-5212-4fe3-b85c-afeb526fc5a5 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f76f2647d622d47d1bc2366-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]
W0417 07:27:52.143235    7108 azurefile.go:546] parsing volumeID(csi-1d0f8ae8da18c5a50a65db3710545ed3eee501241268c97a9a02ef2b26f8fe60) return with error: error parsing volume id: "csi-1d0f8ae8da18c5a50a65db3710545ed3eee501241268c97a9a02ef2b26f8fe60", should at least contain two #
I0417 07:27:52.153755    7108 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-4801/secrets/azure-storage-account-f76f2647d622d47d1bc2366-secret 200 OK in 10 milliseconds
I0417 07:27:52.153755    7108 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\3be97881-5212-4fe3-b85c-afeb526fc5a5\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-1d0f8ae8da18c5a50a65db3710545ed3eee501241268c97a9a02ef2b26f8fe60) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-vthsh csi.storage.k8s.io/pod.namespace:azurefile-4801 csi.storage.k8s.io/pod.uid:3be97881-5212-4fe3-b85c-afeb526fc5a5 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:azure-storage-account-f76f2647d622d47d1bc2366-secret secretnamespace:azurefile-4801 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\f76f2647d622d47d1bc2366]) volumeMountGroup()
I0417 07:27:52.154408    7108 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\3be97881-5212-4fe3-b85c-afeb526fc5a5\volumes\kubernetes.io~csi\test-volume-1\mount
I0417 07:27:52.154408    7108 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\3be97881-5212-4fe3-b85c-afeb526fc5a5\volumes\kubernetes.io~csi\test-volume-1\mount
I0417 07:27:52.156614    7108 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\3be97881-5212-4fe3-b85c-afeb526fc5a5\volumes\kubernetes.io~csi\test-volume-1\mount
I0417 07:27:52.157157    7108 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\3be97881-5212-4fe3-b85c-afeb526fc5a5\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 39 lines ...
I0417 07:28:09.770227    7108 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities
I0417 07:28:09.770227    7108 utils.go:77] GRPC request: {}
I0417 07:28:09.770227    7108 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]}
I0417 07:28:09.771632    7108 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume
I0417 07:28:09.771632    7108 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\f8a3d253-9f92-4d66-a16d-09e621153490\\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-njmqg","csi.storage.k8s.io/pod.namespace":"azurefile-1166","csi.storage.k8s.io/pod.uid":"f8a3d253-9f92-4d66-a16d-09e621153490","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"cache=singleclient","secretName":"smbcreds","server":"52.226.200.247","shareName":"share"},"volume_id":"csi-a24be87ec8f721f8a1dbfe1d4dc43eac149737a922edc3fc382254b8ef90839c"}
I0417 07:28:09.771632    7108 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-a24be87ec8f721f8a1dbfe1d4dc43eac149737a922edc3fc382254b8ef90839c) mount on c:\var\lib\kubelet\pods\f8a3d253-9f92-4d66-a16d-09e621153490\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-njmqg csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:f8a3d253-9f92-4d66-a16d-09e621153490 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:52.226.200.247 shareName:share storageaccount:]
W0417 07:28:09.771632    7108 azurefile.go:546] parsing volumeID(csi-a24be87ec8f721f8a1dbfe1d4dc43eac149737a922edc3fc382254b8ef90839c) return with error: error parsing volume id: "csi-a24be87ec8f721f8a1dbfe1d4dc43eac149737a922edc3fc382254b8ef90839c", should at least contain two #
I0417 07:28:09.775660    7108 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-1166/secrets/smbcreds 200 OK in 4 milliseconds
I0417 07:28:09.775660    7108 nodeserver.go:268] cifsMountPath(c:\var\lib\kubelet\pods\f8a3d253-9f92-4d66-a16d-09e621153490\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-a24be87ec8f721f8a1dbfe1d4dc43eac149737a922edc3fc382254b8ef90839c) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-njmqg csi.storage.k8s.io/pod.namespace:azurefile-1166 csi.storage.k8s.io/pod.uid:f8a3d253-9f92-4d66-a16d-09e621153490 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:cache=singleclient secretName:smbcreds secretnamespace:azurefile-1166 server:52.226.200.247 shareName:share storageaccount:]) mountflags([]) mountOptions([AZURE\USERNAME]) volumeMountGroup()
I0417 07:28:09.775660    7108 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\f8a3d253-9f92-4d66-a16d-09e621153490\volumes\kubernetes.io~csi\test-volume-1\mount
I0417 07:28:09.775660    7108 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\f8a3d253-9f92-4d66-a16d-09e621153490\volumes\kubernetes.io~csi\test-volume-1\mount
I0417 07:28:09.777060    7108 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\f8a3d253-9f92-4d66-a16d-09e621153490\volumes\kubernetes.io~csi\test-volume-1\mount
I0417 07:28:09.777846    7108 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\f8a3d253-9f92-4d66-a16d-09e621153490\volumes\kubernetes.io~csi\test-volume-1\mount
... skipping 710 lines ...
Platform: windows/amd64

Streaming logs below:
I0417 07:10:09.346862    6728 azurefile.go:267] driver userAgent: file.csi.azure.com/e2e-a3f61a5e163bc4536ff4e8a3aac2b0f5e7027564 gc/go1.18.1 (amd64-windows) e2e-test
I0417 07:10:09.361419    6728 azure.go:71] reading cloud config from secret kube-system/azure-cloud-provider
I0417 07:10:09.386263    6728 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
W0417 07:10:09.387685    6728 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
I0417 07:10:09.388237    6728 azure.go:83] could not read cloud config from secret kube-system/azure-cloud-provider
I0417 07:10:09.388237    6728 azure.go:93] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I0417 07:10:09.388237    6728 azure.go:101] read cloud config from file: C:\k\azure.json successfully
I0417 07:10:09.391220    6728 azure_auth.go:245] Using AzurePublicCloud environment
I0417 07:10:09.392426    6728 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I0417 07:10:09.394415    6728 azure_diskclient.go:67] Azure DisksClient using API version: 2021-04-01
... skipping 574 lines ...

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


Summarizing 1 Failure:

[Fail] 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:690

Ran 20 of 34 Specs in 2130.582 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 (2130.59s)
FAIL
FAIL	sigs.k8s.io/azurefile-csi-driver/test/e2e	2130.648s
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 98 lines ...