This job view page is being replaced by Spyglass soon. Check out the new job view.
PRandyzhangx: feat: switch to csi-proxy GA v1
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-24 09:38
Elapsed2h15m
Revision80819fe37aa430e30d0d56a7e11bd6823266c9e3
Refs 728

No Test Failures!


Error lines from build-log.txt

... skipping 71 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11248  100 11248    0     0   199k      0 --:--:-- --:--:-- --:--:--  203k
Downloading https://get.helm.sh/helm-v3.6.3-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull k8sprow.azurecr.io/azurefile-csi:e2e-fc35486a0a312806c5c7c5966e0753afdff731de || make container-all push-manifest
Error response from daemon: manifest for k8sprow.azurecr.io/azurefile-csi:e2e-fc35486a0a312806c5c7c5966e0753afdff731de not found: manifest unknown: manifest tagged by "e2e-fc35486a0a312806c5c7c5966e0753afdff731de" 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-fc35486a0a312806c5c7c5966e0753afdff731de -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=fc35486a0a312806c5c7c5966e0753afdff731de -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2021-07-24T09:43:41Z -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 672 lines ...
#9 9.644 debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.28.1 /usr/local/share/perl/5.28.1 /usr/lib/x86_64-linux-gnu/perl5/5.28 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.28 /usr/share/perl/5.28 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.)
#9 9.644 debconf: falling back to frontend: Teletype
#9 9.683 Setting up libnfsidmap2:amd64 (0.25-5.1) ...
#9 9.701 Setting up python (2.7.16-1) ...
#9 9.725 Setting up nfs-common (1:1.3.4-2.5+deb10u1) ...
#9 9.754 /var/lib/dpkg/info/nfs-common.postinst: 7: /var/lib/dpkg/info/nfs-common.postinst: ucf: not found
#9 9.754 dpkg: error processing package nfs-common (--configure):

#9 9.754  installed nfs-common package post-installation script subprocess returned error exit status 127

#9 9.755 Processing triggers for libc-bin (2.28-10) ...
#9 9.784 Processing triggers for mime-support (3.62) ...
#9 9.821 Errors were encountered while processing:
#9 9.821  nfs-common
#9 9.841 E: Sub-process /usr/bin/dpkg returned an error code (1)
#9 DONE 10.0s

#10 exporting to image
#10 sha256:e8c613e07b0b7ff33893b694f7759a10d42e180f2b4dc349fb57dc6b71dcab00
#10 exporting layers
#10 exporting layers 6.5s done
... skipping 586 lines ...
#7 51.71 debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/aarch64-linux-gnu/perl/5.28.1 /usr/local/share/perl/5.28.1 /usr/lib/aarch64-linux-gnu/perl5/5.28 /usr/share/perl5 /usr/lib/aarch64-linux-gnu/perl/5.28 /usr/share/perl/5.28 /usr/local/lib/site_perl /usr/lib/aarch64-linux-gnu/perl-base) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.)
#7 51.71 debconf: falling back to frontend: Teletype
#7 52.06 Setting up libnfsidmap2:arm64 (0.25-5.1) ...
#7 52.07 Setting up python (2.7.16-1) ...
#7 52.33 Setting up nfs-common (1:1.3.4-2.5+deb10u1) ...
#7 52.39 /var/lib/dpkg/info/nfs-common.postinst: 7: /var/lib/dpkg/info/nfs-common.postinst: ucf: not found
#7 52.40 dpkg: error processing package nfs-common (--configure):

#7 52.40  installed nfs-common package post-installation script subprocess returned error exit status 127

#7 52.40 Processing triggers for libc-bin (2.28-10) ...
#7 52.50 Processing triggers for mime-support (3.62) ...
#7 52.90 Errors were encountered while processing:
#7 52.90  nfs-common
#7 53.02 E: Sub-process /usr/bin/dpkg returned an error code (1)
#7 DONE 53.1s

#9 exporting to image
#9 sha256:e8c613e07b0b7ff33893b694f7759a10d42e180f2b4dc349fb57dc6b71dcab00
#9 exporting layers
#9 exporting layers 6.0s done
... skipping 1230 lines ...
        - name: csi-resizer
          image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.1.0"
          args:
            - "-csi-address=$(ADDRESS)"
            - "-v=2"
            - "-leader-election"
            - '-handle-volume-inuse-error=false'
          env:
            - name: ADDRESS
              value: /csi/csi.sock
          imagePullPolicy: IfNotPresent
          volumeMounts:
            - name: socket-dir
... skipping 135 lines ...
Git Commit: N/A
Go Version: go1.16.6
Platform: linux/amd64

Streaming logs below:
STEP: Building a namespace api object, basename azurefile
E0724 09:53:58.043973   14065 azure_config.go:45] Failed to get cloud-config from secret: failed to get secret /: resource name may not be empty
I0724 09:53:58.045591   14065 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0724 09:53:58.045615   14065 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0724 09:53:58.045619   14065 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0724 09:53:58.045623   14065 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0724 09:53:58.045627   14065 driver.go:112] Enabling volume access mode: SINGLE_NODE_WRITER
I0724 09:53:58.045632   14065 driver.go:112] Enabling volume access mode: SINGLE_NODE_READER_ONLY
... skipping 123 lines ...
Jul 24 09:56:05.608: INFO: PersistentVolumeClaim pvc-dg2jd found but phase is Pending instead of Bound.
Jul 24 09:56:07.662: INFO: PersistentVolumeClaim pvc-dg2jd found and phase=Bound (1m38.68407653s)
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
Jul 24 09:56:07.823: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-6jzwq" in namespace "azurefile-1318" to be "Succeeded or Failed"
Jul 24 09:56:07.875: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 52.247583ms
Jul 24 09:56:09.930: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107323346s
Jul 24 09:56:11.985: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.161646296s
Jul 24 09:56:14.040: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.217456807s
Jul 24 09:56:16.094: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.271351428s
Jul 24 09:56:18.149: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.326155387s
... skipping 427 lines ...
Jul 24 10:10:57.857: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.034468145s
Jul 24 10:10:59.912: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.089102775s
Jul 24 10:11:01.968: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.144918287s
Jul 24 10:11:04.021: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.198437783s
Jul 24 10:11:06.075: INFO: Pod "azurefile-volume-tester-6jzwq": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.252130859s
Jul 24 10:11:08.076: INFO: deleting Pod "azurefile-1318"/"azurefile-volume-tester-6jzwq"
Jul 24 10:11:08.160: INFO: Error getting logs for pod azurefile-volume-tester-6jzwq: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-6jzwq)
STEP: Deleting pod azurefile-volume-tester-6jzwq in namespace azurefile-1318
Jul 24 10:11:08.215: INFO: deleting PVC "azurefile-1318"/"pvc-dg2jd"
Jul 24 10:11:08.215: INFO: Deleting PersistentVolumeClaim "pvc-dg2jd"
STEP: waiting for claim's PV "pvc-a4c73479-fcf7-4ba8-8d6f-30c5e4fbc6ac" to be deleted
Jul 24 10:11:08.382: INFO: Waiting up to 10m0s for PersistentVolume pvc-a4c73479-fcf7-4ba8-8d6f-30c5e4fbc6ac to get deleted
Jul 24 10:11:08.434: INFO: PersistentVolume pvc-a4c73479-fcf7-4ba8-8d6f-30c5e4fbc6ac found and phase=Bound (51.809324ms)
... skipping 4 lines ...
STEP: Collecting events from namespace "azurefile-1318".
STEP: Found 6 events.
Jul 24 10:11:13.651: INFO: At 2021-07-24 09:54:28 +0000 UTC - event for pvc-dg2jd: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-1318/pvc-dg2jd"
Jul 24 10:11:13.651: INFO: At 2021-07-24 09:54:28 +0000 UTC - event for pvc-dg2jd: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 10:11:13.651: INFO: At 2021-07-24 09:56:05 +0000 UTC - event for pvc-dg2jd: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-a4c73479-fcf7-4ba8-8d6f-30c5e4fbc6ac
Jul 24 10:11:13.651: INFO: At 2021-07-24 09:56:07 +0000 UTC - event for azurefile-volume-tester-6jzwq: {default-scheduler } Scheduled: Successfully assigned azurefile-1318/azurefile-volume-tester-6jzwq to 7747k8s001
Jul 24 10:11:13.651: INFO: At 2021-07-24 09:56:08 +0000 UTC - event for azurefile-volume-tester-6jzwq: {kubelet 7747k8s001} FailedMount: MountVolume.MountDevice failed for volume "pvc-a4c73479-fcf7-4ba8-8d6f-30c5e4fbc6ac" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 10:11:13.651: INFO: At 2021-07-24 09:58:10 +0000 UTC - event for azurefile-volume-tester-6jzwq: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-plr5r]: timed out waiting for the condition
Jul 24 10:11:13.704: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 10:11:13.704: INFO: 
Jul 24 10:11:13.761: INFO: 
Logging node info for node 7747k8s000
Jul 24 10:11:13.813: INFO: Node Info: &Node{ObjectMeta:{7747k8s000   /api/v1/nodes/7747k8s000 896e3dea-e295-4ddd-997f-08f6ba18b6da 5421 0 2021-07-24 09:42:56 +0000 UTC <nil> <nil> map[agentpool:windowspool1 beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:Standard_D4s_v3 beta.kubernetes.io/os:windows failure-domain.beta.kubernetes.io/region:westus2 failure-domain.beta.kubernetes.io/zone:1 kubernetes.azure.com/cluster:kubetest-u8k85kqd kubernetes.azure.com/role:agent kubernetes.io/arch:amd64 kubernetes.io/hostname:7747k8s000 kubernetes.io/os:windows kubernetes.io/role:agent node-role.kubernetes.io/agent: node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.17763 storageprofile:managed storagetier:Premium_LRS topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:1] map[node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{kubelet.exe Update v1 2021-07-24 09:42:56 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:agentpool":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.azure.com/cluster":{},"f:kubernetes.azure.com/role":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:storageprofile":{},"f:storagetier":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-azure-disk":{},"f:cpu":{},"f:ephemeral-storage":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-azure-disk":{},"f:cpu":{},"f:ephemeral-storage":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}} {kubectl-label Update v1 2021-07-24 09:42:58 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/agent":{}}}}} {kube-controller-manager Update v1 2021-07-24 09:43:01 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}}}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-u8k85kqd/providers/Microsoft.Compute/virtualMachines/7747k8s000,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{17179398144 0} {<nil>} 16776756Ki BinarySI},pods: {{30 0} {<nil>} 30 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{15031914496 0} {<nil>} 14679604Ki BinarySI},pods: {{30 0} {<nil>} 30 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2021-07-24 10:09:27 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2021-07-24 10:09:27 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2021-07-24 10:09:27 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2021-07-24 10:09:27 +0000 UTC,LastTransitionTime:2021-07-24 09:43:06 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:7747k8s000,},NodeAddress{Type:InternalIP,Address:10.240.0.65,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:7747k8s000,SystemUUID:21AD05C0-A178-4CE0-AAC0-03830B6AA603,BootID:,KernelVersion:10.0.17763.1879,OSImage:Windows Server 2019 Datacenter,ContainerRuntimeVersion:containerd://1.4.4+unknown,KubeletVersion:v1.19.13,KubeProxyVersion:v1.19.13,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore:ltsc2019],SizeBytes:2469755813,},ContainerImage{Names:[k8sprow.azurecr.io/azurefile-csi@sha256:013fd1177dd2d03fd8247a5e9315ce89d185d512ec09eb2c5b225b5594c64391 k8sprow.azurecr.io/azurefile-csi:e2e-fc35486a0a312806c5c7c5966e0753afdff731de],SizeBytes:115042208,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:8863840b419194a408ab8fa21961f4a317fb4e7ad8a8b783fe65677c0c7e4f0a mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.2.0],SizeBytes:112790089,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:aae4d193ef1480387294e07d164d48c70be090f7f95f03a6f70ef1bac225e9cc mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.3.0],SizeBytes:112193336,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v1.2.1-alpha.1-windows-1809-amd64],SizeBytes:108116897,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.0.1-alpha.1-windows-1809-amd64],SizeBytes:107834550,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes/pause:1.4.1],SizeBytes:107267487,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes/pause@sha256:565501aebaf23dd687a04ae41511819c854b0447aab91acf70217cc56885ea47 mcr.microsoft.com/oss/kubernetes/pause:3.4.1-windows-1809-amd64 mcr.microsoft.com/oss/kubernetes/pause:3.4.1],SizeBytes:106226157,},ContainerImage{Names:[mcr.microsoft.com/windows/nanoserver:1809],SizeBytes:101341959,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 65 lines ...
• Failure [1007.752 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:103

  Unexpected error:
      <*errors.errorString | 0xc0003c4a70>: {
          s: "Gave up after waiting 15m0s for pod \"azurefile-volume-tester-6jzwq\" to be \"Succeeded or Failed\"",
      }
      Gave up after waiting 15m0s for pod "azurefile-volume-tester-6jzwq" to be "Succeeded or Failed"
  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 28 lines ...
Jul 24 10:11:35.683: INFO: PersistentVolumeClaim pvc-9qrfb found but phase is Pending instead of Bound.
Jul 24 10:11:37.738: INFO: PersistentVolumeClaim pvc-9qrfb found and phase=Bound (20.591506452s)
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
Jul 24 10:11:37.902: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-x8794" in namespace "azurefile-694" to be "Succeeded or Failed"
Jul 24 10:11:37.954: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 51.95879ms
Jul 24 10:11:40.009: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 2.106344211s
Jul 24 10:11:42.063: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 4.160286885s
Jul 24 10:11:44.117: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 6.214717488s
Jul 24 10:11:46.171: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 8.268512506s
Jul 24 10:11:48.225: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 10.322950797s
... skipping 427 lines ...
Jul 24 10:26:28.300: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.397516036s
Jul 24 10:26:30.360: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.458237866s
Jul 24 10:26:32.420: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.517293107s
Jul 24 10:26:34.483: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.580303541s
Jul 24 10:26:36.540: INFO: Pod "azurefile-volume-tester-x8794": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.637546597s
Jul 24 10:26:38.541: INFO: deleting Pod "azurefile-694"/"azurefile-volume-tester-x8794"
Jul 24 10:26:38.648: INFO: Error getting logs for pod azurefile-volume-tester-x8794: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-x8794)
STEP: Deleting pod azurefile-volume-tester-x8794 in namespace azurefile-694
Jul 24 10:26:38.706: INFO: deleting PVC "azurefile-694"/"pvc-9qrfb"
Jul 24 10:26:38.706: INFO: Deleting PersistentVolumeClaim "pvc-9qrfb"
STEP: waiting for claim's PV "pvc-a8707978-1468-4ad1-b771-a9d8f7de3ed4" to be deleted
Jul 24 10:26:38.879: INFO: Waiting up to 10m0s for PersistentVolume pvc-a8707978-1468-4ad1-b771-a9d8f7de3ed4 to get deleted
Jul 24 10:26:38.934: INFO: PersistentVolume pvc-a8707978-1468-4ad1-b771-a9d8f7de3ed4 found and phase=Bound (55.215942ms)
... skipping 6 lines ...
STEP: Collecting events from namespace "azurefile-694".
STEP: Found 7 events.
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:11:17 +0000 UTC - event for pvc-9qrfb: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-694/pvc-9qrfb"
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:11:17 +0000 UTC - event for pvc-9qrfb: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:11:36 +0000 UTC - event for pvc-9qrfb: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-a8707978-1468-4ad1-b771-a9d8f7de3ed4
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:11:37 +0000 UTC - event for azurefile-volume-tester-x8794: {default-scheduler } Scheduled: Successfully assigned azurefile-694/azurefile-volume-tester-x8794 to 7747k8s000
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:11:38 +0000 UTC - event for azurefile-volume-tester-x8794: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-a8707978-1468-4ad1-b771-a9d8f7de3ed4" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:13:40 +0000 UTC - event for azurefile-volume-tester-x8794: {kubelet 7747k8s000} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[default-token-rgnt2 test-volume-1]: timed out waiting for the condition
Jul 24 10:26:54.277: INFO: At 2021-07-24 10:15:54 +0000 UTC - event for azurefile-volume-tester-x8794: {kubelet 7747k8s000} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-rgnt2]: timed out waiting for the condition
Jul 24 10:26:54.333: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 10:26:54.333: INFO: 
Jul 24 10:26:54.389: INFO: 
Logging node info for node 7747k8s000
... skipping 66 lines ...
• Failure [940.658 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create a pod with volume mount subpath [file.csi.azure.com] [Windows] [It]
  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:147

  Unexpected error:
      <*errors.errorString | 0xc000577190>: {
          s: "Gave up after waiting 15m0s for pod \"azurefile-volume-tester-x8794\" to be \"Succeeded or Failed\"",
      }
      Gave up after waiting 15m0s for pod "azurefile-volume-tester-x8794" to be "Succeeded or Failed"
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:690
------------------------------
Dynamic Provisioning 
  should create multiple PV objects, bind to PVCs and attach all to different pods on the same node [kubernetes.io/azure-file] [file.csi.azure.com] [Windows]
... skipping 21 lines ...
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod is running
Jul 24 10:32:00.232: INFO: deleting Pod "azurefile-3274"/"azurefile-volume-tester-k6lb6"
Jul 24 10:32:00.326: INFO: Error getting logs for pod azurefile-volume-tester-k6lb6: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-k6lb6)
STEP: Deleting pod azurefile-volume-tester-k6lb6 in namespace azurefile-3274
Jul 24 10:32:00.383: INFO: deleting PVC "azurefile-3274"/"pvc-ws958"
Jul 24 10:32:00.383: INFO: Deleting PersistentVolumeClaim "pvc-ws958"
STEP: waiting for claim's PV "pvc-2cd667a1-5f78-4377-a2bf-6c5de89547c4" to be deleted
Jul 24 10:32:00.558: INFO: Waiting up to 10m0s for PersistentVolume pvc-2cd667a1-5f78-4377-a2bf-6c5de89547c4 to get deleted
Jul 24 10:32:00.613: INFO: PersistentVolume pvc-2cd667a1-5f78-4377-a2bf-6c5de89547c4 found and phase=Bound (54.763441ms)
... skipping 4 lines ...
Jul 24 10:32:10.780: INFO: deleting StorageClass azurefile-3274-file.csi.azure.com-dynamic-sc-nhndf
STEP: Collecting events from namespace "azurefile-3274".
STEP: Found 7 events.
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:26:57 +0000 UTC - event for pvc-ws958: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:26:57 +0000 UTC - event for pvc-ws958: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-3274/pvc-ws958"
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:26:58 +0000 UTC - event for pvc-ws958: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-2cd667a1-5f78-4377-a2bf-6c5de89547c4
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:27:00 +0000 UTC - event for azurefile-volume-tester-k6lb6: {kubelet 7747k8s001} FailedMount: MountVolume.MountDevice failed for volume "pvc-2cd667a1-5f78-4377-a2bf-6c5de89547c4" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:27:00 +0000 UTC - event for azurefile-volume-tester-k6lb6: {default-scheduler } Scheduled: Successfully assigned azurefile-3274/azurefile-volume-tester-k6lb6 to 7747k8s001
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:29:03 +0000 UTC - event for azurefile-volume-tester-k6lb6: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[default-token-xc5kk test-volume-1]: timed out waiting for the condition
Jul 24 10:32:10.892: INFO: At 2021-07-24 10:31:20 +0000 UTC - event for azurefile-volume-tester-k6lb6: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-xc5kk]: timed out waiting for the condition
Jul 24 10:32:10.946: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 10:32:10.946: INFO: 
Jul 24 10:32:11.002: INFO: 
... skipping 67 lines ...
• Failure [316.640 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create multiple PV objects, bind to PVCs and attach all to different pods on the same node [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:178

  Unexpected error:
      <*errors.errorString | 0xc0003c4510>: {
          s: "timed out waiting for the condition",
      }
      timed out waiting for the condition
  occurred

... skipping 32 lines ...
Jul 24 10:32:32.661: INFO: PersistentVolumeClaim pvc-d6jfb found but phase is Pending instead of Bound.
Jul 24 10:32:34.718: INFO: PersistentVolumeClaim pvc-d6jfb found and phase=Bound (20.623840257s)
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
Jul 24 10:32:34.891: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-p6klj" in namespace "azurefile-495" to be "Error status code"
Jul 24 10:32:34.955: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 64.914308ms
Jul 24 10:32:37.012: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.121266019s
Jul 24 10:32:39.066: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.175906633s
Jul 24 10:32:41.122: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.231199788s
Jul 24 10:32:43.177: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.286849512s
Jul 24 10:32:45.234: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.343833426s
... skipping 427 lines ...
Jul 24 10:47:25.743: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.852031193s
Jul 24 10:47:27.799: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.908171217s
Jul 24 10:47:29.855: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.964157439s
Jul 24 10:47:31.910: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.019514395s
Jul 24 10:47:33.965: INFO: Pod "azurefile-volume-tester-p6klj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.074821561s
Jul 24 10:47:35.967: INFO: deleting Pod "azurefile-495"/"azurefile-volume-tester-p6klj"
Jul 24 10:47:36.074: INFO: Error getting logs for pod azurefile-volume-tester-p6klj: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-p6klj)
STEP: Deleting pod azurefile-volume-tester-p6klj in namespace azurefile-495
Jul 24 10:47:36.131: INFO: deleting PVC "azurefile-495"/"pvc-d6jfb"
Jul 24 10:47:36.131: INFO: Deleting PersistentVolumeClaim "pvc-d6jfb"
STEP: waiting for claim's PV "pvc-e9d9c5ae-122a-4851-9613-362e0a02799d" to be deleted
Jul 24 10:47:36.296: INFO: Waiting up to 10m0s for PersistentVolume pvc-e9d9c5ae-122a-4851-9613-362e0a02799d to get deleted
Jul 24 10:47:36.349: INFO: PersistentVolume pvc-e9d9c5ae-122a-4851-9613-362e0a02799d found and phase=Bound (53.682655ms)
... skipping 4 lines ...
STEP: Collecting events from namespace "azurefile-495".
STEP: Found 7 events.
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:32:14 +0000 UTC - event for pvc-d6jfb: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-495/pvc-d6jfb"
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:32:14 +0000 UTC - event for pvc-d6jfb: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:32:33 +0000 UTC - event for pvc-d6jfb: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-e9d9c5ae-122a-4851-9613-362e0a02799d
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:32:34 +0000 UTC - event for azurefile-volume-tester-p6klj: {default-scheduler } Scheduled: Successfully assigned azurefile-495/azurefile-volume-tester-p6klj to 7747k8s000
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:32:35 +0000 UTC - event for azurefile-volume-tester-p6klj: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-e9d9c5ae-122a-4851-9613-362e0a02799d" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:34:37 +0000 UTC - event for azurefile-volume-tester-p6klj: {kubelet 7747k8s000} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-fsgl2]: timed out waiting for the condition
Jul 24 10:47:41.593: INFO: At 2021-07-24 10:43:42 +0000 UTC - event for azurefile-volume-tester-p6klj: {kubelet 7747k8s000} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[default-token-fsgl2 test-volume-1]: timed out waiting for the condition
Jul 24 10:47:41.647: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 10:47:41.647: INFO: 
Jul 24 10:47:41.702: INFO: 
Logging node info for node 7747k8s000
... skipping 66 lines ...
• Failure [930.603 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 and mount it as readOnly in a pod [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:222

  Unexpected error:
      <*errors.errorString | 0xc00001eb30>: {
          s: "Gave up after waiting 15m0s for pod \"azurefile-volume-tester-p6klj\" to be \"Error status code\"",
      }
      Gave up after waiting 15m0s for pod "azurefile-volume-tester-p6klj" to be "Error status code"
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:724
------------------------------
Dynamic Provisioning 
  should create a deployment object, write and read to it, delete the pod and write and read to it again [kubernetes.io/azure-file] [file.csi.azure.com] [Windows]
... skipping 173 lines ...
Jul 24 10:52:41.324: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-k98r8-589cb7f4cd\" is progressing."}}, CollisionCount:(*int32)(nil)}
Jul 24 10:52:43.324: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-k98r8-589cb7f4cd\" is progressing."}}, CollisionCount:(*int32)(nil)}
Jul 24 10:52:45.325: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-k98r8-589cb7f4cd\" is progressing."}}, CollisionCount:(*int32)(nil)}
Jul 24 10:52:47.325: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-k98r8-589cb7f4cd\" is progressing."}}, CollisionCount:(*int32)(nil)}
Jul 24 10:52:47.379: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-k98r8-589cb7f4cd\" is progressing."}}, CollisionCount:(*int32)(nil)}
Jul 24 10:52:47.379: INFO: deleting Deployment "azurefile-9947"/"azurefile-volume-tester-k98r8"
Jul 24 10:52:47.379: INFO: Error getting logs for pod : resource name may not be empty
Jul 24 10:52:47.436: INFO: deleting PVC "azurefile-9947"/"pvc-wprfc"
Jul 24 10:52:47.436: INFO: Deleting PersistentVolumeClaim "pvc-wprfc"
STEP: waiting for claim's PV "pvc-fd7c7cad-765b-4984-b5bb-0de035f60541" to be deleted
Jul 24 10:52:47.610: INFO: Waiting up to 10m0s for PersistentVolume pvc-fd7c7cad-765b-4984-b5bb-0de035f60541 to get deleted
Jul 24 10:52:47.663: INFO: PersistentVolume pvc-fd7c7cad-765b-4984-b5bb-0de035f60541 found and phase=Bound (53.506449ms)
Jul 24 10:52:52.720: INFO: PersistentVolume pvc-fd7c7cad-765b-4984-b5bb-0de035f60541 was removed
... skipping 5 lines ...
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:44 +0000 UTC - event for pvc-wprfc: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-9947/pvc-wprfc"
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:44 +0000 UTC - event for pvc-wprfc: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:45 +0000 UTC - event for pvc-wprfc: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-fd7c7cad-765b-4984-b5bb-0de035f60541
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:47 +0000 UTC - event for azurefile-volume-tester-k98r8: {deployment-controller } ScalingReplicaSet: Scaled up replica set azurefile-volume-tester-k98r8-589cb7f4cd to 1
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:47 +0000 UTC - event for azurefile-volume-tester-k98r8-589cb7f4cd: {replicaset-controller } SuccessfulCreate: Created pod: azurefile-volume-tester-k98r8-589cb7f4cd-gpqjl
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:47 +0000 UTC - event for azurefile-volume-tester-k98r8-589cb7f4cd-gpqjl: {default-scheduler } Scheduled: Successfully assigned azurefile-9947/azurefile-volume-tester-k98r8-589cb7f4cd-gpqjl to 7747k8s001
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:47:47 +0000 UTC - event for azurefile-volume-tester-k98r8-589cb7f4cd-gpqjl: {kubelet 7747k8s001} FailedMount: MountVolume.MountDevice failed for volume "pvc-fd7c7cad-765b-4984-b5bb-0de035f60541" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:49:50 +0000 UTC - event for azurefile-volume-tester-k98r8-589cb7f4cd-gpqjl: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-jn4wz]: timed out waiting for the condition
Jul 24 10:52:52.900: INFO: At 2021-07-24 10:52:04 +0000 UTC - event for azurefile-volume-tester-k98r8-589cb7f4cd-gpqjl: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[default-token-jn4wz test-volume-1]: timed out waiting for the condition
Jul 24 10:52:52.955: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 10:52:52.955: INFO: 
Jul 24 10:52:53.023: INFO: 
Logging node info for node 7747k8s000
... skipping 66 lines ...
• Failure [311.485 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create a deployment object, write and read to it, delete the pod and write and read to it again [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:248

  Unexpected error:
      <*errors.errorString | 0xc000a2a4b0>: {
          s: "error waiting for deployment \"azurefile-volume-tester-k98r8\" status to match expectation: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:\"Available\", Status:\"False\", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:\"MinimumReplicasUnavailable\", Message:\"Deployment does not have minimum availability.\"}, v1.DeploymentCondition{Type:\"Progressing\", Status:\"True\", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:\"ReplicaSetUpdated\", Message:\"ReplicaSet \\\"azurefile-volume-tester-k98r8-589cb7f4cd\\\" is progressing.\"}}, CollisionCount:(*int32)(nil)}",
      }
      error waiting for deployment "azurefile-volume-tester-k98r8" status to match expectation: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63762720467, loc:(*time.Location)(0x33e4e60)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-k98r8-589cb7f4cd\" is progressing."}}, CollisionCount:(*int32)(nil)}
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:435
------------------------------
Dynamic Provisioning 
  should delete PV with reclaimPolicy "Delete" [kubernetes.io/azure-file] [file.csi.azure.com] [Windows]
... skipping 118 lines ...
Jul 24 10:53:24.142: INFO: PersistentVolumeClaim pvc-zp27n found but phase is Pending instead of Bound.
Jul 24 10:53:26.197: INFO: PersistentVolumeClaim pvc-zp27n found and phase=Bound (2.117708366s)
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
Jul 24 10:53:26.374: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-zkqrz" in namespace "azurefile-3090" to be "Succeeded or Failed"
Jul 24 10:53:26.431: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 57.188262ms
Jul 24 10:53:28.489: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.115056464s
Jul 24 10:53:30.545: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.170892822s
Jul 24 10:53:32.601: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.226589371s
Jul 24 10:53:34.657: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.282696327s
Jul 24 10:53:36.714: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.339678998s
... skipping 427 lines ...
Jul 24 11:08:17.017: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.642708105s
Jul 24 11:08:19.073: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.69867505s
Jul 24 11:08:21.128: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.754477813s
Jul 24 11:08:23.187: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.812732554s
Jul 24 11:08:25.243: INFO: Pod "azurefile-volume-tester-zkqrz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.869030846s
Jul 24 11:08:27.244: INFO: deleting Pod "azurefile-3090"/"azurefile-volume-tester-zkqrz"
Jul 24 11:08:27.349: INFO: Error getting logs for pod azurefile-volume-tester-zkqrz: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-zkqrz)
STEP: Deleting pod azurefile-volume-tester-zkqrz in namespace azurefile-3090
Jul 24 11:08:27.406: INFO: deleting PVC "azurefile-3090"/"pvc-zp27n"
Jul 24 11:08:27.407: INFO: Deleting PersistentVolumeClaim "pvc-zp27n"
STEP: waiting for claim's PV "pvc-ffd3390b-65e2-4dc0-9b4e-3009665cf047" to be deleted
Jul 24 11:08:27.578: INFO: Waiting up to 10m0s for PersistentVolume pvc-ffd3390b-65e2-4dc0-9b4e-3009665cf047 to get deleted
Jul 24 11:08:27.632: INFO: PersistentVolume pvc-ffd3390b-65e2-4dc0-9b4e-3009665cf047 found and phase=Bound (54.031118ms)
... skipping 4 lines ...
STEP: Collecting events from namespace "azurefile-3090".
STEP: Found 6 events.
Jul 24 11:08:32.862: INFO: At 2021-07-24 10:53:24 +0000 UTC - event for pvc-zp27n: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-3090/pvc-zp27n"
Jul 24 11:08:32.862: INFO: At 2021-07-24 10:53:24 +0000 UTC - event for pvc-zp27n: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 11:08:32.862: INFO: At 2021-07-24 10:53:24 +0000 UTC - event for pvc-zp27n: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-ffd3390b-65e2-4dc0-9b4e-3009665cf047
Jul 24 11:08:32.862: INFO: At 2021-07-24 10:53:26 +0000 UTC - event for azurefile-volume-tester-zkqrz: {default-scheduler } Scheduled: Successfully assigned azurefile-3090/azurefile-volume-tester-zkqrz to 7747k8s000
Jul 24 11:08:32.862: INFO: At 2021-07-24 10:53:26 +0000 UTC - event for azurefile-volume-tester-zkqrz: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-ffd3390b-65e2-4dc0-9b4e-3009665cf047" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 11:08:32.862: INFO: At 2021-07-24 10:55:29 +0000 UTC - event for azurefile-volume-tester-zkqrz: {kubelet 7747k8s000} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-z4bsn]: timed out waiting for the condition
Jul 24 11:08:32.916: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 11:08:32.916: INFO: 
Jul 24 11:08:32.971: INFO: 
Logging node info for node 7747k8s000
Jul 24 11:08:33.025: INFO: Node Info: &Node{ObjectMeta:{7747k8s000   /api/v1/nodes/7747k8s000 896e3dea-e295-4ddd-997f-08f6ba18b6da 16482 0 2021-07-24 09:42:56 +0000 UTC <nil> <nil> map[agentpool:windowspool1 beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:Standard_D4s_v3 beta.kubernetes.io/os:windows failure-domain.beta.kubernetes.io/region:westus2 failure-domain.beta.kubernetes.io/zone:1 kubernetes.azure.com/cluster:kubetest-u8k85kqd kubernetes.azure.com/role:agent kubernetes.io/arch:amd64 kubernetes.io/hostname:7747k8s000 kubernetes.io/os:windows kubernetes.io/role:agent node-role.kubernetes.io/agent: node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.17763 storageprofile:managed storagetier:Premium_LRS topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:1] map[node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{kubelet.exe Update v1 2021-07-24 09:42:56 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:agentpool":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.azure.com/cluster":{},"f:kubernetes.azure.com/role":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:storageprofile":{},"f:storagetier":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-azure-disk":{},"f:cpu":{},"f:ephemeral-storage":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-azure-disk":{},"f:cpu":{},"f:ephemeral-storage":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}} {kubectl-label Update v1 2021-07-24 09:42:58 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/agent":{}}}}} {kube-controller-manager Update v1 2021-07-24 09:43:01 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}}}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-u8k85kqd/providers/Microsoft.Compute/virtualMachines/7747k8s000,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{17179398144 0} {<nil>} 16776756Ki BinarySI},pods: {{30 0} {<nil>} 30 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{15031914496 0} {<nil>} 14679604Ki BinarySI},pods: {{30 0} {<nil>} 30 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2021-07-24 11:04:29 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2021-07-24 11:04:29 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2021-07-24 11:04:29 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2021-07-24 11:04:29 +0000 UTC,LastTransitionTime:2021-07-24 09:43:06 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:7747k8s000,},NodeAddress{Type:InternalIP,Address:10.240.0.65,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:7747k8s000,SystemUUID:21AD05C0-A178-4CE0-AAC0-03830B6AA603,BootID:,KernelVersion:10.0.17763.1879,OSImage:Windows Server 2019 Datacenter,ContainerRuntimeVersion:containerd://1.4.4+unknown,KubeletVersion:v1.19.13,KubeProxyVersion:v1.19.13,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore:ltsc2019],SizeBytes:2469755813,},ContainerImage{Names:[k8sprow.azurecr.io/azurefile-csi@sha256:013fd1177dd2d03fd8247a5e9315ce89d185d512ec09eb2c5b225b5594c64391 k8sprow.azurecr.io/azurefile-csi:e2e-fc35486a0a312806c5c7c5966e0753afdff731de],SizeBytes:115042208,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:8863840b419194a408ab8fa21961f4a317fb4e7ad8a8b783fe65677c0c7e4f0a mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.2.0],SizeBytes:112790089,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:aae4d193ef1480387294e07d164d48c70be090f7f95f03a6f70ef1bac225e9cc mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.3.0],SizeBytes:112193336,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v1.2.1-alpha.1-windows-1809-amd64],SizeBytes:108116897,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.0.1-alpha.1-windows-1809-amd64],SizeBytes:107834550,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes/pause:1.4.1],SizeBytes:107267487,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes/pause@sha256:565501aebaf23dd687a04ae41511819c854b0447aab91acf70217cc56885ea47 mcr.microsoft.com/oss/kubernetes/pause:3.4.1-windows-1809-amd64 mcr.microsoft.com/oss/kubernetes/pause:3.4.1],SizeBytes:106226157,},ContainerImage{Names:[mcr.microsoft.com/windows/nanoserver:1809],SizeBytes:101341959,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 65 lines ...
• Failure [912.008 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 and resize it [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:326

  Unexpected error:
      <*errors.errorString | 0xc000d8e150>: {
          s: "Gave up after waiting 15m0s for pod \"azurefile-volume-tester-zkqrz\" to be \"Succeeded or Failed\"",
      }
      Gave up after waiting 15m0s for pod "azurefile-volume-tester-zkqrz" to be "Succeeded or Failed"
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:690
------------------------------
Dynamic Provisioning 
  should create a vhd disk volume on demand [kubernetes.io/azure-file] [file.csi.azure.com][disk]
... skipping 298 lines ...
Jul 24 11:09:00.764: INFO: PersistentVolumeClaim pvc-76p87 found but phase is Pending instead of Bound.
Jul 24 11:09:02.820: INFO: PersistentVolumeClaim pvc-76p87 found and phase=Bound (2.111507381s)
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
Jul 24 11:09:02.990: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lhrgg" in namespace "azurefile-3033" to be "Succeeded or Failed"
Jul 24 11:09:03.046: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 55.75457ms
Jul 24 11:09:05.102: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.112111963s
Jul 24 11:09:07.160: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.169398896s
Jul 24 11:09:09.218: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.227564411s
Jul 24 11:09:11.275: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.284341112s
Jul 24 11:09:13.333: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.342363814s
... skipping 427 lines ...
Jul 24 11:23:53.764: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.77375339s
Jul 24 11:23:55.820: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.829982629s
Jul 24 11:23:57.876: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.886196896s
Jul 24 11:23:59.933: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.942927658s
Jul 24 11:24:01.989: INFO: Pod "azurefile-volume-tester-lhrgg": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.998844461s
Jul 24 11:24:03.990: INFO: deleting Pod "azurefile-3033"/"azurefile-volume-tester-lhrgg"
Jul 24 11:24:04.098: INFO: Error getting logs for pod azurefile-volume-tester-lhrgg: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-lhrgg)
STEP: Deleting pod azurefile-volume-tester-lhrgg in namespace azurefile-3033
Jul 24 11:24:04.156: INFO: deleting PVC "azurefile-3033"/"pvc-76p87"
Jul 24 11:24:04.156: INFO: Deleting PersistentVolumeClaim "pvc-76p87"
STEP: waiting for claim's PV "pvc-9b18600b-be8d-4d88-a45b-116cb036f9b7" to be deleted
Jul 24 11:24:04.325: INFO: Waiting up to 10m0s for PersistentVolume pvc-9b18600b-be8d-4d88-a45b-116cb036f9b7 to get deleted
Jul 24 11:24:04.379: INFO: PersistentVolume pvc-9b18600b-be8d-4d88-a45b-116cb036f9b7 found and phase=Bound (54.578507ms)
... skipping 63 lines ...
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:08:58 +0000 UTC - event for pvc-wskgt: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:08:58 +0000 UTC - event for pvc-wskgt: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-a020b641-a471-4ccb-a9e0-ab8ad0d25ab2
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:00 +0000 UTC - event for pvc-76p87: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-9b18600b-be8d-4d88-a45b-116cb036f9b7
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:00 +0000 UTC - event for pvc-76p87: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:00 +0000 UTC - event for pvc-76p87: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-3033/pvc-76p87"
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:02 +0000 UTC - event for azurefile-volume-tester-lhrgg: {default-scheduler } Scheduled: Successfully assigned azurefile-3033/azurefile-volume-tester-lhrgg to 7747k8s000
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:03 +0000 UTC - event for azurefile-volume-tester-lhrgg: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-a020b641-a471-4ccb-a9e0-ab8ad0d25ab2" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:03 +0000 UTC - event for azurefile-volume-tester-lhrgg: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-ca10e1a7-e4fd-481f-afb5-358583304c1a" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:03 +0000 UTC - event for azurefile-volume-tester-lhrgg: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-6c06ba36-d9ef-4937-a6e8-36964fcb125f" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 11:24:31.612: INFO: At 2021-07-24 11:09:04 +0000 UTC - event for azurefile-volume-tester-lhrgg: {kubelet 7747k8s000} FailedMount: MountVolume.MountDevice failed for volume "pvc-9b18600b-be8d-4d88-a45b-116cb036f9b7" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 11:24:31.666: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 11:24:31.666: INFO: 
Jul 24 11:24:31.721: INFO: 
Logging node info for node 7747k8s000
Jul 24 11:24:31.776: INFO: Node Info: &Node{ObjectMeta:{7747k8s000   /api/v1/nodes/7747k8s000 896e3dea-e295-4ddd-997f-08f6ba18b6da 20622 0 2021-07-24 09:42:56 +0000 UTC <nil> <nil> map[agentpool:windowspool1 beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:Standard_D4s_v3 beta.kubernetes.io/os:windows failure-domain.beta.kubernetes.io/region:westus2 failure-domain.beta.kubernetes.io/zone:1 kubernetes.azure.com/cluster:kubetest-u8k85kqd kubernetes.azure.com/role:agent kubernetes.io/arch:amd64 kubernetes.io/hostname:7747k8s000 kubernetes.io/os:windows kubernetes.io/role:agent node-role.kubernetes.io/agent: node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.17763 storageprofile:managed storagetier:Premium_LRS topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:1] map[node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{kubelet.exe Update v1 2021-07-24 09:42:56 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:agentpool":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.azure.com/cluster":{},"f:kubernetes.azure.com/role":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:storageprofile":{},"f:storagetier":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-azure-disk":{},"f:cpu":{},"f:ephemeral-storage":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-azure-disk":{},"f:cpu":{},"f:ephemeral-storage":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}} {kubectl-label Update v1 2021-07-24 09:42:58 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/agent":{}}}}} {kube-controller-manager Update v1 2021-07-24 09:43:01 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}}}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-u8k85kqd/providers/Microsoft.Compute/virtualMachines/7747k8s000,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{17179398144 0} {<nil>} 16776756Ki BinarySI},pods: {{30 0} {<nil>} 30 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{136912564224 0} {<nil>} 133703676Ki BinarySI},memory: {{15031914496 0} {<nil>} 14679604Ki BinarySI},pods: {{30 0} {<nil>} 30 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2021-07-24 11:24:30 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2021-07-24 11:24:30 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2021-07-24 11:24:30 +0000 UTC,LastTransitionTime:2021-07-24 09:42:48 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2021-07-24 11:24:30 +0000 UTC,LastTransitionTime:2021-07-24 09:43:06 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:7747k8s000,},NodeAddress{Type:InternalIP,Address:10.240.0.65,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:7747k8s000,SystemUUID:21AD05C0-A178-4CE0-AAC0-03830B6AA603,BootID:,KernelVersion:10.0.17763.1879,OSImage:Windows Server 2019 Datacenter,ContainerRuntimeVersion:containerd://1.4.4+unknown,KubeletVersion:v1.19.13,KubeProxyVersion:v1.19.13,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore:ltsc2019],SizeBytes:2469755813,},ContainerImage{Names:[k8sprow.azurecr.io/azurefile-csi@sha256:013fd1177dd2d03fd8247a5e9315ce89d185d512ec09eb2c5b225b5594c64391 k8sprow.azurecr.io/azurefile-csi:e2e-fc35486a0a312806c5c7c5966e0753afdff731de],SizeBytes:115042208,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:8863840b419194a408ab8fa21961f4a317fb4e7ad8a8b783fe65677c0c7e4f0a mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.2.0],SizeBytes:112790089,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:aae4d193ef1480387294e07d164d48c70be090f7f95f03a6f70ef1bac225e9cc mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.3.0],SizeBytes:112193336,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v1.2.1-alpha.1-windows-1809-amd64],SizeBytes:108116897,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.0.1-alpha.1-windows-1809-amd64],SizeBytes:107834550,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes/pause:1.4.1],SizeBytes:107267487,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes/pause@sha256:565501aebaf23dd687a04ae41511819c854b0447aab91acf70217cc56885ea47 mcr.microsoft.com/oss/kubernetes/pause:3.4.1-windows-1809-amd64 mcr.microsoft.com/oss/kubernetes/pause:3.4.1],SizeBytes:106226157,},ContainerImage{Names:[mcr.microsoft.com/windows/nanoserver:1809],SizeBytes:101341959,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
Jul 24 11:24:31.776: INFO: 
... skipping 64 lines ...
• Failure [945.839 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create a pod with multiple volumes [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:585

  Unexpected error:
      <*errors.errorString | 0xc0008fee70>: {
          s: "Gave up after waiting 15m0s for pod \"azurefile-volume-tester-lhrgg\" to be \"Succeeded or Failed\"",
      }
      Gave up after waiting 15m0s for pod "azurefile-volume-tester-lhrgg" to be "Succeeded or Failed"
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:690
------------------------------
Dynamic Provisioning 
  should create a pod, write and read to it, take a volume snapshot, and validate whether it is ready to use [file.csi.azure.com]
... skipping 37 lines ...
there is a driver pod which has restarted
======================================================================================
2021/07/24 11:24:36 Check successfully
Jul 24 11:24:36.745: INFO: >>> kubeConfig: /root/tmp973082530/kubeconfig/kubeconfig.westus2.json
2021/07/24 11:24:36 run script: test/utils/get_storage_account_secret_name.sh
2021/07/24 11:24:37 got output: azure-storage-account-f021196a3eb324fe5952ad3-secret
, error: <nil>
2021/07/24 11:24:37 got storage account secret name: azure-storage-account-f021196a3eb324fe5952ad3-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"
Jul 24 11:24:37.204: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-wctrc] to have phase Bound
Jul 24 11:24:37.264: INFO: PersistentVolumeClaim pvc-wctrc found but phase is Pending instead of Bound.
Jul 24 11:24:39.319: INFO: PersistentVolumeClaim pvc-wctrc found and phase=Bound (2.115551315s)
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
Jul 24 11:24:39.496: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-wx59k" in namespace "azurefile-552" to be "Succeeded or Failed"
Jul 24 11:24:39.551: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 54.433204ms
Jul 24 11:24:41.607: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.110543538s
Jul 24 11:24:43.662: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.166048718s
Jul 24 11:24:45.718: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.221361994s
Jul 24 11:24:47.774: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.278240842s
Jul 24 11:24:49.833: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.33639227s
... skipping 386 lines ...
Jul 24 11:38:05.353: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m25.856884924s
Jul 24 11:38:07.409: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m27.912451633s
Jul 24 11:38:09.462: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m29.966218549s
Jul 24 11:38:11.517: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m32.020416195s
Jul 24 11:38:13.570: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m34.073743716s
Jul 24 11:38:15.624: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m36.127294756s
{"component":"entrypoint","file":"prow/entrypoint/run.go:165","func":"k8s.io/test-infra/prow/entrypoint.Options.ExecuteProcess","level":"error","msg":"Process did not finish before 2h0m0s timeout","severity":"error","time":"2021-07-24T11:38:16Z"}
++ early_exit_handler
++ '[' -n 189 ']'
++ kill -TERM 189
++ cleanup_dind
++ [[ true == \t\r\u\e ]]
++ echo 'Cleaning up after docker'
... skipping 51 lines ...
Jul 24 11:39:29.611: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.114834184s
Jul 24 11:39:31.666: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.169593612s
Jul 24 11:39:33.726: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.229803319s
Jul 24 11:39:35.784: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.288224471s
Jul 24 11:39:37.841: INFO: Pod "azurefile-volume-tester-wx59k": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.34433457s
Jul 24 11:39:39.841: INFO: deleting Pod "azurefile-552"/"azurefile-volume-tester-wx59k"
Jul 24 11:39:39.946: INFO: Error getting logs for pod azurefile-volume-tester-wx59k: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-wx59k)
STEP: Deleting pod azurefile-volume-tester-wx59k in namespace azurefile-552
Jul 24 11:39:40.003: INFO: deleting PVC "azurefile-552"/"pvc-wctrc"
Jul 24 11:39:40.003: INFO: Deleting PersistentVolumeClaim "pvc-wctrc"
STEP: waiting for claim's PV "pvc-8e538b6e-91f2-4124-a87c-514d0f45a03c" to be deleted
Jul 24 11:39:40.170: INFO: Waiting up to 10m0s for PersistentVolume pvc-8e538b6e-91f2-4124-a87c-514d0f45a03c to get deleted
Jul 24 11:39:40.231: INFO: PersistentVolume pvc-8e538b6e-91f2-4124-a87c-514d0f45a03c found and phase=Bound (60.881361ms)
... skipping 4 lines ...
Jul 24 11:39:50.392: INFO: deleting StorageClass azurefile-552-file.csi.azure.com-dynamic-sc-44kjx
STEP: Collecting events from namespace "azurefile-552".
STEP: Found 7 events.
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:24:37 +0000 UTC - event for pvc-wctrc: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } ProvisioningSucceeded: Successfully provisioned volume pvc-8e538b6e-91f2-4124-a87c-514d0f45a03c
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:24:37 +0000 UTC - event for pvc-wctrc: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:24:37 +0000 UTC - event for pvc-wctrc: {file.csi.azure.com_k8s-master-77474357-0_cbc9103f-0b76-44b2-805a-0289eaf71bf1 } Provisioning: External provisioner is provisioning volume for claim "azurefile-552/pvc-wctrc"
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:24:39 +0000 UTC - event for azurefile-volume-tester-wx59k: {kubelet 7747k8s001} FailedMount: MountVolume.MountDevice failed for volume "pvc-8e538b6e-91f2-4124-a87c-514d0f45a03c" : kubernetes.io/csi: attacher.MountDevice failed to create newCsiDriverClient: driver name file.csi.azure.com not found in the list of registered CSI drivers
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:24:39 +0000 UTC - event for azurefile-volume-tester-wx59k: {default-scheduler } Scheduled: Successfully assigned azurefile-552/azurefile-volume-tester-wx59k to 7747k8s001
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:26:42 +0000 UTC - event for azurefile-volume-tester-wx59k: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 default-token-jvnc2]: timed out waiting for the condition
Jul 24 11:39:50.502: INFO: At 2021-07-24 11:33:28 +0000 UTC - event for azurefile-volume-tester-wx59k: {kubelet 7747k8s001} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[default-token-jvnc2 test-volume-1]: timed out waiting for the condition
Jul 24 11:39:50.555: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Jul 24 11:39:50.555: INFO: 
Jul 24 11:39:50.609: INFO: 
... skipping 67 lines ...
• Failure [916.885 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 (Bring Your Own Key) [file.csi.azure.com] [Windows] [It]
  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:643

  Unexpected error:
      <*errors.errorString | 0xc0003c51e0>: {
          s: "Gave up after waiting 15m0s for pod \"azurefile-volume-tester-wx59k\" to be \"Succeeded or Failed\"",
      }
      Gave up after waiting 15m0s for pod "azurefile-volume-tester-wx59k" to be "Succeeded or Failed"
  occurred

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:690
------------------------------
Dynamic Provisioning 
  should create a volume on demand with useDataPlaneAPI [file.csi.azure.com] [Windows]
... skipping 19 lines ...
Jul 24 11:39:53.901: INFO: PersistentVolumeClaim pvc-vcpb7 found but phase is Pending instead of Bound.
Jul 24 11:39:55.976: INFO: PersistentVolumeClaim pvc-vcpb7 found and phase=Bound (2.131323485s)
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
Jul 24 11:39:56.155: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7ksf5" in namespace "azurefile-1351" to be "Succeeded or Failed"
Jul 24 11:39:56.216: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 61.037287ms
Jul 24 11:39:58.270: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.114636584s
Jul 24 11:40:00.323: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.168210984s
Jul 24 11:40:02.378: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.222743874s
Jul 24 11:40:04.431: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.27648831s
Jul 24 11:40:06.487: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.331910819s
... skipping 378 lines ...
Jul 24 11:53:05.550: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 13m9.39462842s
Jul 24 11:53:07.605: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 13m11.449847402s
Jul 24 11:53:09.659: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 13m13.503834667s
Jul 24 11:53:11.712: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 13m15.557379542s
Jul 24 11:53:13.768: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 13m17.612851639s
Jul 24 11:53:15.822: INFO: Pod "azurefile-volume-tester-7ksf5": Phase="Pending", Reason="", readiness=false. Elapsed: 13m19.666990195s
{"component":"entrypoint","file":"prow/entrypoint/run.go:255","func":"k8s.io/test-infra/prow/entrypoint.gracefullyTerminate","level":"error","msg":"Process did not exit before 15m0s grace period","severity":"error","time":"2021-07-24T11:53:16Z"}
{"component":"entrypoint","error":"os: process already finished","file":"prow/entrypoint/run.go:257","func":"k8s.io/test-infra/prow/entrypoint.gracefullyTerminate","level":"error","msg":"Could not kill process after grace period","severity":"error","time":"2021-07-24T11:53:16Z"}