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 0 failed / 0 succeeded
Started2022-04-18 13:34
Elapsed2h15m
Revision406a0d30aff10d48525d3e58710a2b1ac4047aa0
Refs 988

No Test Failures!


Error lines from build-log.txt

... skipping 673 lines ...
certificate.cert-manager.io "selfsigned-cert" deleted
# Create secret for AzureClusterIdentity
./hack/create-identity-secret.sh
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
make[2]: Nothing to be done for 'kubectl'.
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Error from server (NotFound): secrets "cluster-identity-secret" not found
secret/cluster-identity-secret created
secret/cluster-identity-secret labeled
# Deploy CAPI
curl --retry 3 -sSL https://github.com/kubernetes-sigs/cluster-api/releases/download/v1.1.2/cluster-api-components.yaml | /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/envsubst-v2.0.0-20210730161058-179042472c46 | kubectl apply -f -
namespace/capi-system created
customresourcedefinition.apiextensions.k8s.io/clusterclasses.cluster.x-k8s.io created
... skipping 129 lines ...
# Wait for the kubeconfig to become available.
timeout --foreground 300 bash -c "while ! kubectl get secrets | grep capz-c79crl-kubeconfig; do sleep 1; done"
capz-c79crl-kubeconfig                 cluster.x-k8s.io/secret               1      1s
# Get kubeconfig and store it locally.
kubectl get secrets capz-c79crl-kubeconfig -o json | jq -r .data.value | base64 --decode > ./kubeconfig
timeout --foreground 600 bash -c "while ! kubectl --kubeconfig=./kubeconfig get nodes | grep control-plane; do sleep 1; done"
error: the server doesn't have a resource type "nodes"
capz-c79crl-control-plane-9cs5n   NotReady   control-plane,master   2s    v1.23.5
run "kubectl --kubeconfig=./kubeconfig ..." to work with the new target cluster
make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Waiting for 1 control plane machine(s), 2 worker machine(s), and 2 windows machine(s) to become Ready
node/capz-c79c-9hwfc condition met
node/capz-c79c-xjbpd condition met
... skipping 1037 lines ...
          image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.4.0"
          args:
            - "-csi-address=$(ADDRESS)"
            - "-v=2"
            - "-leader-election"
            - "--leader-election-namespace=kube-system"
            - '-handle-volume-inuse-error=false'
            - '-timeout=120s'
            - '-feature-gates=RecoverVolumeExpansionFailure=true'
          env:
            - name: ADDRESS
              value: /csi/csi.sock
          imagePullPolicy: IfNotPresent
... skipping 148 lines ...
Git Commit: N/A
Go Version: go1.18.1
Platform: linux/amd64

Streaming logs below:
STEP: Building a namespace api object, basename azurefile
W0418 13:53:15.632969   36728 azure.go:78] InitializeCloudFromSecret: failed to get cloud config from secret /: failed to get secret /: resource name may not be empty
I0418 13:53:15.635684   36728 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0418 13:53:15.635704   36728 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME
I0418 13:53:15.635708   36728 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0418 13:53:15.635713   36728 driver.go:93] Enabling controller service capability: EXPAND_VOLUME
I0418 13:53:15.635717   36728 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
I0418 13:53:15.635721   36728 driver.go:112] Enabling volume access mode: SINGLE_NODE_WRITER
... skipping 23 lines ...
Apr 18 13:53:38.518: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-crtxf] to have phase Bound
Apr 18 13:53:38.572: INFO: PersistentVolumeClaim pvc-crtxf found and phase=Bound (53.698684ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with an error
Apr 18 13:53:38.735: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-5ppb4" in namespace "azurefile-8081" to be "Error status code"
Apr 18 13:53:38.794: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 59.217846ms
Apr 18 13:53:40.848: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.113483763s
Apr 18 13:53:42.902: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.167785439s
Apr 18 13:53:44.957: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.222020138s
Apr 18 13:53:47.011: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.275979005s
Apr 18 13:53:49.069: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.334022698s
... skipping 182 lines ...
Apr 18 14:00:05.764: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m27.028987797s
Apr 18 14:00:07.822: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m29.087517014s
Apr 18 14:00:09.881: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m31.146471479s
Apr 18 14:00:11.939: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m33.204307369s
Apr 18 14:00:13.998: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m35.263052375s
Apr 18 14:00:16.057: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Pending", Reason="", readiness=false. Elapsed: 6m37.322536409s
Apr 18 14:00:18.116: INFO: Pod "azurefile-volume-tester-5ppb4": Phase="Failed", Reason="", readiness=false. Elapsed: 6m39.381458257s
STEP: Saw pod failure
Apr 18 14:00:18.116: INFO: Pod "azurefile-volume-tester-5ppb4" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 14:00:18.193: INFO: deleting Pod "azurefile-8081"/"azurefile-volume-tester-5ppb4"
Apr 18 14:00:18.253: INFO: Pod azurefile-volume-tester-5ppb4 has the following logs: 
STEP: Deleting pod azurefile-volume-tester-5ppb4 in namespace azurefile-8081
Apr 18 14:00:18.318: INFO: deleting PVC "azurefile-8081"/"pvc-crtxf"
Apr 18 14:00:18.318: INFO: Deleting PersistentVolumeClaim "pvc-crtxf"
... skipping 7 lines ...
STEP: Collecting events from namespace "azurefile-8081".
STEP: Found 6 events.
Apr 18 14:00:18.601: INFO: At 2022-04-18 13:53:38 +0000 UTC - event for azurefile-volume-tester-5ppb4: {default-scheduler } Scheduled: Successfully assigned azurefile-8081/azurefile-volume-tester-5ppb4 to capz-c79c-9hwfc
Apr 18 14:00:18.601: INFO: At 2022-04-18 13:53:50 +0000 UTC - event for azurefile-volume-tester-5ppb4: {kubelet capz-c79c-9hwfc} Pulling: Pulling image "mcr.microsoft.com/windows/servercore:ltsc2022"
Apr 18 14:00:18.601: INFO: At 2022-04-18 13:58:15 +0000 UTC - event for azurefile-volume-tester-5ppb4: {kubelet capz-c79c-9hwfc} Pulled: Successfully pulled image "mcr.microsoft.com/windows/servercore:ltsc2022" in 4m25.529223s
Apr 18 14:00:18.601: INFO: At 2022-04-18 13:58:15 +0000 UTC - event for azurefile-volume-tester-5ppb4: {kubelet capz-c79c-9hwfc} Created: Created container volume-tester
Apr 18 14:00:18.601: INFO: At 2022-04-18 14:00:15 +0000 UTC - event for azurefile-volume-tester-5ppb4: {kubelet capz-c79c-9hwfc} Failed: Error: context deadline exceeded
Apr 18 14:00:18.601: INFO: At 2022-04-18 14:00:16 +0000 UTC - event for azurefile-volume-tester-5ppb4: {kubelet capz-c79c-9hwfc} Pulled: Container image "mcr.microsoft.com/windows/servercore:ltsc2022" already present on machine
Apr 18 14:00:18.655: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 14:00:18.655: INFO: 
Apr 18 14:00:18.763: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 14:00:18.820: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 2716 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 13:58:42 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 13:58:42 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 13:58:42 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 13:58:42 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 146 lines ...
Apr 18 14:00:23.546: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jfxrq] to have phase Bound
Apr 18 14:00:23.600: INFO: PersistentVolumeClaim pvc-jfxrq found and phase=Bound (53.772532ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:00:23.765: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4fslb" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 14:00:23.819: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Pending", Reason="", readiness=false. Elapsed: 53.992803ms
Apr 18 14:00:25.874: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.108393412s
Apr 18 14:00:27.930: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.164633344s
Apr 18 14:00:29.988: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.222548974s
Apr 18 14:00:32.045: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.279343844s
Apr 18 14:00:34.100: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.334994328s
Apr 18 14:00:36.157: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Running", Reason="", readiness=true. Elapsed: 12.391265761s
Apr 18 14:00:38.212: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Running", Reason="", readiness=true. Elapsed: 14.446983057s
Apr 18 14:00:40.269: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Running", Reason="", readiness=true. Elapsed: 16.504198009s
Apr 18 14:00:42.325: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Running", Reason="", readiness=true. Elapsed: 18.560233434s
Apr 18 14:00:44.381: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Running", Reason="", readiness=true. Elapsed: 20.615702514s
Apr 18 14:00:46.437: INFO: Pod "azurefile-volume-tester-4fslb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.672003619s
STEP: Saw pod success
Apr 18 14:00:46.437: INFO: Pod "azurefile-volume-tester-4fslb" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 14:00:46.547: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-7lwdw] to have phase Bound
Apr 18 14:00:46.601: INFO: PersistentVolumeClaim pvc-7lwdw found and phase=Bound (53.867616ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:00:46.764: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-p726w" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 14:00:46.818: INFO: Pod "azurefile-volume-tester-p726w": Phase="Pending", Reason="", readiness=false. Elapsed: 53.934735ms
Apr 18 14:00:48.872: INFO: Pod "azurefile-volume-tester-p726w": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107345833s
Apr 18 14:00:50.929: INFO: Pod "azurefile-volume-tester-p726w": Phase="Pending", Reason="", readiness=false. Elapsed: 4.164291544s
Apr 18 14:00:52.984: INFO: Pod "azurefile-volume-tester-p726w": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219897876s
Apr 18 14:00:55.040: INFO: Pod "azurefile-volume-tester-p726w": Phase="Pending", Reason="", readiness=false. Elapsed: 8.275990637s
Apr 18 14:00:57.096: INFO: Pod "azurefile-volume-tester-p726w": Phase="Running", Reason="", readiness=true. Elapsed: 10.331939957s
Apr 18 14:00:59.152: INFO: Pod "azurefile-volume-tester-p726w": Phase="Running", Reason="", readiness=true. Elapsed: 12.387735516s
Apr 18 14:01:01.209: INFO: Pod "azurefile-volume-tester-p726w": Phase="Running", Reason="", readiness=true. Elapsed: 14.444480629s
Apr 18 14:01:03.263: INFO: Pod "azurefile-volume-tester-p726w": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.49903182s
STEP: Saw pod success
Apr 18 14:01:03.263: INFO: Pod "azurefile-volume-tester-p726w" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 14:01:03.377: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-zwx6v] to have phase Bound
Apr 18 14:01:03.431: INFO: PersistentVolumeClaim pvc-zwx6v found and phase=Bound (53.934362ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:01:03.594: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-fj9jq" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 14:01:03.648: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Pending", Reason="", readiness=false. Elapsed: 53.600798ms
Apr 18 14:01:05.703: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.108847911s
Apr 18 14:01:07.759: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.165331039s
Apr 18 14:01:09.816: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.221750717s
Apr 18 14:01:11.872: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.278166868s
Apr 18 14:01:13.929: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Running", Reason="", readiness=true. Elapsed: 10.334987958s
Apr 18 14:01:15.985: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Running", Reason="", readiness=true. Elapsed: 12.391141854s
Apr 18 14:01:18.042: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Running", Reason="", readiness=true. Elapsed: 14.447519268s
Apr 18 14:01:20.097: INFO: Pod "azurefile-volume-tester-fj9jq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.502986062s
STEP: Saw pod success
Apr 18 14:01:20.097: INFO: Pod "azurefile-volume-tester-fj9jq" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 14:01:20.209: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-ldrgc] to have phase Bound
Apr 18 14:01:20.263: INFO: PersistentVolumeClaim pvc-ldrgc found and phase=Bound (53.987366ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:01:20.427: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-wlzg4" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 14:01:20.480: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Pending", Reason="", readiness=false. Elapsed: 53.213661ms
Apr 18 14:01:22.535: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.108150882s
Apr 18 14:01:24.592: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.165000075s
Apr 18 14:01:26.650: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.222939639s
Apr 18 14:01:28.706: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.278704888s
Apr 18 14:01:30.761: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Running", Reason="", readiness=true. Elapsed: 10.333874977s
Apr 18 14:01:32.817: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Running", Reason="", readiness=true. Elapsed: 12.389596589s
Apr 18 14:01:34.872: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Running", Reason="", readiness=true. Elapsed: 14.445485282s
Apr 18 14:01:36.931: INFO: Pod "azurefile-volume-tester-wlzg4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.504064296s
STEP: Saw pod success
Apr 18 14:01:36.931: INFO: Pod "azurefile-volume-tester-wlzg4" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 14:01:37.044: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-s7826] to have phase Bound
Apr 18 14:01:37.098: INFO: PersistentVolumeClaim pvc-s7826 found and phase=Bound (53.618599ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:01:37.262: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-r9kn5" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 14:01:37.317: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Pending", Reason="", readiness=false. Elapsed: 54.004922ms
Apr 18 14:01:39.372: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.109843251s
Apr 18 14:01:41.429: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.166379151s
Apr 18 14:01:43.485: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.222256321s
Apr 18 14:01:45.541: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.278899342s
Apr 18 14:01:47.597: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Running", Reason="", readiness=true. Elapsed: 10.334570631s
Apr 18 14:01:49.654: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Running", Reason="", readiness=true. Elapsed: 12.391032919s
Apr 18 14:01:51.711: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Running", Reason="", readiness=true. Elapsed: 14.448127208s
Apr 18 14:01:53.767: INFO: Pod "azurefile-volume-tester-r9kn5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.504102227s
STEP: Saw pod success
Apr 18 14:01:53.767: INFO: Pod "azurefile-volume-tester-r9kn5" satisfied condition "Succeeded or Failed"
STEP: setting up the PV
STEP: creating a PV
STEP: setting up the PVC
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Apr 18 14:01:53.879: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-48fc6] to have phase Bound
Apr 18 14:01:53.934: INFO: PersistentVolumeClaim pvc-48fc6 found and phase=Bound (54.424502ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:01:54.099: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-mj47m" in namespace "azurefile-2540" to be "Succeeded or Failed"
Apr 18 14:01:54.153: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Pending", Reason="", readiness=false. Elapsed: 53.847774ms
Apr 18 14:01:56.207: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.108478158s
Apr 18 14:01:58.263: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.163912539s
Apr 18 14:02:00.319: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220565506s
Apr 18 14:02:02.376: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.277381916s
Apr 18 14:02:04.433: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Running", Reason="", readiness=true. Elapsed: 10.334246643s
Apr 18 14:02:06.488: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Running", Reason="", readiness=true. Elapsed: 12.389610605s
Apr 18 14:02:08.544: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Running", Reason="", readiness=true. Elapsed: 14.445014176s
Apr 18 14:02:10.599: INFO: Pod "azurefile-volume-tester-mj47m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.500671918s
STEP: Saw pod success
Apr 18 14:02:10.600: INFO: Pod "azurefile-volume-tester-mj47m" satisfied condition "Succeeded or Failed"
Apr 18 14:02:10.600: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-mj47m"
Apr 18 14:02:10.669: INFO: Pod azurefile-volume-tester-mj47m has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-mj47m in namespace azurefile-2540
Apr 18 14:02:10.730: INFO: deleting PVC "azurefile-2540"/"pvc-48fc6"
Apr 18 14:02:10.731: INFO: Deleting PersistentVolumeClaim "pvc-48fc6"
... skipping 143 lines ...
Apr 18 14:02:17.640: INFO: PersistentVolumeClaim pvc-8n8lg found but phase is Pending instead of Bound.
Apr 18 14:02:19.696: INFO: PersistentVolumeClaim pvc-8n8lg found and phase=Bound (2.109458354s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:02:19.860: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vn5mv" in namespace "azurefile-5466" to be "Succeeded or Failed"
Apr 18 14:02:19.913: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Pending", Reason="", readiness=false. Elapsed: 53.66407ms
Apr 18 14:02:21.968: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107881368s
Apr 18 14:02:24.024: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.164165398s
Apr 18 14:02:26.080: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220177498s
Apr 18 14:02:28.136: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.275857265s
Apr 18 14:02:30.191: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Running", Reason="", readiness=true. Elapsed: 10.331615734s
Apr 18 14:02:32.251: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Running", Reason="", readiness=true. Elapsed: 12.390829325s
Apr 18 14:02:34.308: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Running", Reason="", readiness=true. Elapsed: 14.448078105s
Apr 18 14:02:36.364: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Running", Reason="", readiness=true. Elapsed: 16.504776732s
Apr 18 14:02:38.420: INFO: Pod "azurefile-volume-tester-vn5mv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.560124768s
STEP: Saw pod success
Apr 18 14:02:38.420: INFO: Pod "azurefile-volume-tester-vn5mv" satisfied condition "Succeeded or Failed"
Apr 18 14:02:38.420: INFO: deleting Pod "azurefile-5466"/"azurefile-volume-tester-vn5mv"
Apr 18 14:02:38.483: INFO: Pod azurefile-volume-tester-vn5mv has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-vn5mv in namespace azurefile-5466
Apr 18 14:02:38.547: INFO: deleting PVC "azurefile-5466"/"pvc-8n8lg"
Apr 18 14:02:38.547: INFO: Deleting PersistentVolumeClaim "pvc-8n8lg"
... skipping 33 lines ...
Apr 18 14:02:40.621: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-j2mgp] to have phase Bound
Apr 18 14:02:40.674: INFO: PersistentVolumeClaim pvc-j2mgp found and phase=Bound (53.444027ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:02:40.840: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lrz5v" in namespace "azurefile-2790" to be "Succeeded or Failed"
Apr 18 14:02:40.894: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Pending", Reason="", readiness=false. Elapsed: 54.08813ms
Apr 18 14:02:42.947: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107858459s
Apr 18 14:02:45.004: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Pending", Reason="", readiness=false. Elapsed: 4.164419363s
Apr 18 14:02:47.061: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220951789s
Apr 18 14:02:49.116: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Pending", Reason="", readiness=false. Elapsed: 8.276716885s
Apr 18 14:02:51.172: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Pending", Reason="", readiness=false. Elapsed: 10.332582168s
Apr 18 14:02:53.233: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Running", Reason="", readiness=true. Elapsed: 12.393640817s
Apr 18 14:02:55.290: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Running", Reason="", readiness=true. Elapsed: 14.449979853s
Apr 18 14:02:57.346: INFO: Pod "azurefile-volume-tester-lrz5v": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.506107694s
STEP: Saw pod success
Apr 18 14:02:57.346: INFO: Pod "azurefile-volume-tester-lrz5v" satisfied condition "Succeeded or Failed"
Apr 18 14:02:57.346: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-lrz5v"
Apr 18 14:02:57.408: INFO: Pod azurefile-volume-tester-lrz5v has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-lrz5v in namespace azurefile-2790
Apr 18 14:02:57.470: INFO: deleting PVC "azurefile-2790"/"pvc-j2mgp"
Apr 18 14:02:57.471: INFO: Deleting PersistentVolumeClaim "pvc-j2mgp"
... skipping 231 lines ...
Apr 18 14:08:22.697: INFO: PersistentVolumeClaim pvc-nrxxn found but phase is Pending instead of Bound.
Apr 18 14:08:24.752: INFO: PersistentVolumeClaim pvc-nrxxn found but phase is Pending instead of Bound.
STEP: Collecting events from namespace "azurefile-5194".
STEP: Found 7 events.
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:03:26 +0000 UTC - event for pvc-nrxxn: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-5194/pvc-nrxxn"
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:03:26 +0000 UTC - event for pvc-nrxxn: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:04:17 +0000 UTC - event for pvc-nrxxn: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-5194-file.csi.azure.com-dynamic-sc-sjxlr": rpc error: code = Internal desc = failed to ensure storage account: Failed to create private endpoint for storage account(f386faeae73df489e95595f), resourceGroup(capz-c79crl), error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 429, RawError: {

  "error": {

    "code": "RetryableError",
    "message": "A retryable error occurred.",

    "details": [
      {
        "code": "ReferencedResourceNotProvisioned",
        "message": "Cannot proceed with operation because resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/networkInterfaces/capz-c79c-9hwfc-nic/ipConfigurations/pipConfig used by resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/virtualNetworks/capz-c79crl-vnet/subnets/node-subnet is not in Succeeded state. Resource is in Updating state and the last operation that updated/is updating the resource is PutNicOperation."
      }
    ]
  }
}
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:05:09 +0000 UTC - event for pvc-nrxxn: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-5194-file.csi.azure.com-dynamic-sc-sjxlr": rpc error: code = Internal desc = failed to ensure storage account: Failed to create private endpoint for storage account(f8917d7001d9a4c5c90fdea), resourceGroup(capz-c79crl), error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 429, RawError: {

  "error": {

    "code": "RetryableError",
    "message": "A retryable error occurred.",

    "details": [
      {
        "code": "ReferencedResourceNotProvisioned",
        "message": "Cannot proceed with operation because resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/networkInterfaces/capz-c79c-9hwfc-nic/ipConfigurations/pipConfig used by resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/virtualNetworks/capz-c79crl-vnet/subnets/node-subnet is not in Succeeded state. Resource is in Updating state and the last operation that updated/is updating the resource is PutNicOperation."
      }
    ]
  }
}
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:06:03 +0000 UTC - event for pvc-nrxxn: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-5194-file.csi.azure.com-dynamic-sc-sjxlr": rpc error: code = Internal desc = failed to ensure storage account: Failed to create private endpoint for storage account(fc91fb20dc08c4e8c899f3f), resourceGroup(capz-c79crl), error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 429, RawError: {

  "error": {

    "code": "RetryableError",
    "message": "A retryable error occurred.",

    "details": [
      {
        "code": "ReferencedResourceNotProvisioned",
        "message": "Cannot proceed with operation because resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/networkInterfaces/capz-c79c-9hwfc-nic/ipConfigurations/pipConfig used by resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/virtualNetworks/capz-c79crl-vnet/subnets/node-subnet is not in Succeeded state. Resource is in Updating state and the last operation that updated/is updating the resource is PutNicOperation."
      }
    ]
  }
}
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:06:59 +0000 UTC - event for pvc-nrxxn: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-5194-file.csi.azure.com-dynamic-sc-sjxlr": rpc error: code = Internal desc = failed to ensure storage account: Failed to create private endpoint for storage account(f47bf570d6f4d47a8b0fb31), resourceGroup(capz-c79crl), error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 429, RawError: {

  "error": {

    "code": "RetryableError",
    "message": "A retryable error occurred.",

    "details": [
      {
        "code": "ReferencedResourceNotProvisioned",
        "message": "Cannot proceed with operation because resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/networkInterfaces/capz-c79c-9hwfc-nic/ipConfigurations/pipConfig used by resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/virtualNetworks/capz-c79crl-vnet/subnets/node-subnet is not in Succeeded state. Resource is in Updating state and the last operation that updated/is updating the resource is PutNicOperation."
      }
    ]
  }
}
Apr 18 14:08:26.812: INFO: At 2022-04-18 14:07:57 +0000 UTC - event for pvc-nrxxn: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-5194-file.csi.azure.com-dynamic-sc-sjxlr": rpc error: code = Internal desc = failed to ensure storage account: Failed to create private endpoint for storage account(fa238f1e0a9f747938a0a72), resourceGroup(capz-c79crl), error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 429, RawError: {

  "error": {

    "code": "RetryableError",
    "message": "A retryable error occurred.",

    "details": [
      {
        "code": "ReferencedResourceNotProvisioned",
        "message": "Cannot proceed with operation because resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/networkInterfaces/capz-c79c-9hwfc-nic/ipConfigurations/pipConfig used by resource /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Network/virtualNetworks/capz-c79crl-vnet/subnets/node-subnet is not in Succeeded state. Resource is in Updating state and the last operation that updated/is updating the resource is PutNicOperation."
      }
    ]
... skipping 120 lines ...
• Failure [303.428 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 | 0xc000497860>: {
          s: "PersistentVolumeClaims [pvc-nrxxn] not all in phase Bound within 5m0s",
      }
      PersistentVolumeClaims [pvc-nrxxn] not all in phase Bound within 5m0s
  occurred

... skipping 21 lines ...
Apr 18 14:08:30.238: INFO: PersistentVolumeClaim pvc-8h5qq found but phase is Pending instead of Bound.
Apr 18 14:08:32.293: INFO: PersistentVolumeClaim pvc-8h5qq found and phase=Bound (2.119744888s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:08:32.457: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vpj2r" in namespace "azurefile-1353" to be "Succeeded or Failed"
Apr 18 14:08:32.510: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 53.155806ms
Apr 18 14:08:34.564: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107331344s
Apr 18 14:08:36.620: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 4.162860892s
Apr 18 14:08:38.674: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 6.217734664s
Apr 18 14:08:40.729: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 8.272526899s
Apr 18 14:08:42.784: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 10.32725644s
... skipping 427 lines ...
Apr 18 14:23:22.388: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.931218404s
Apr 18 14:23:24.442: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.985704694s
Apr 18 14:23:26.498: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.041144453s
Apr 18 14:23:28.552: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.09542759s
Apr 18 14:23:30.607: INFO: Pod "azurefile-volume-tester-vpj2r": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.150675934s
Apr 18 14:23:32.608: INFO: deleting Pod "azurefile-1353"/"azurefile-volume-tester-vpj2r"
Apr 18 14:23:32.674: INFO: Error getting logs for pod azurefile-volume-tester-vpj2r: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-vpj2r)
STEP: Deleting pod azurefile-volume-tester-vpj2r in namespace azurefile-1353
Apr 18 14:23:32.733: INFO: deleting PVC "azurefile-1353"/"pvc-8h5qq"
Apr 18 14:23:32.733: INFO: Deleting PersistentVolumeClaim "pvc-8h5qq"
STEP: waiting for claim's PV "pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0" to be deleted
Apr 18 14:23:32.899: INFO: Waiting up to 10m0s for PersistentVolume pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0 to get deleted
Apr 18 14:23:32.952: INFO: PersistentVolume pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0 found and phase=Bound (53.727267ms)
... skipping 12 lines ...
STEP: Collecting events from namespace "azurefile-1353".
STEP: Found 6 events.
Apr 18 14:24:18.609: INFO: At 2022-04-18 14:08:30 +0000 UTC - event for pvc-8h5qq: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-1353/pvc-8h5qq"
Apr 18 14:24:18.609: INFO: At 2022-04-18 14:08:30 +0000 UTC - event for pvc-8h5qq: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 14:24:18.609: INFO: At 2022-04-18 14:08:30 +0000 UTC - event for pvc-8h5qq: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0
Apr 18 14:24:18.609: INFO: At 2022-04-18 14:08:32 +0000 UTC - event for azurefile-volume-tester-vpj2r: {default-scheduler } Scheduled: Successfully assigned azurefile-1353/azurefile-volume-tester-vpj2r to capz-c79c-9hwfc
Apr 18 14:24:18.609: INFO: At 2022-04-18 14:08:37 +0000 UTC - event for azurefile-volume-tester-vpj2r: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#fileprefix-pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\fileprefix-pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-075b2d37-fc36-42a5-a310-731bbee6e7a0\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 14:24:18.609: INFO: At 2022-04-18 14:10:35 +0000 UTC - event for azurefile-volume-tester-vpj2r: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1]: timed out waiting for the condition
Apr 18 14:24:18.663: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 14:24:18.663: INFO: 
Apr 18 14:24:18.730: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 14:24:18.787: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 6933 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 14:24:14 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 14:24:14 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 14:24:14 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 14:24:14 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 113 lines ...
• Failure [951.752 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:150

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

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:691
------------------------------
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 19 lines ...
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod is running
Apr 18 14:29:24.591: INFO: deleting Pod "azurefile-2888"/"azurefile-volume-tester-bzd5q"
Apr 18 14:29:24.662: INFO: Error getting logs for pod azurefile-volume-tester-bzd5q: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-bzd5q)
STEP: Deleting pod azurefile-volume-tester-bzd5q in namespace azurefile-2888
Apr 18 14:29:24.717: INFO: deleting PVC "azurefile-2888"/"pvc-5chwj"
Apr 18 14:29:24.717: INFO: Deleting PersistentVolumeClaim "pvc-5chwj"
STEP: waiting for claim's PV "pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1" to be deleted
Apr 18 14:29:24.882: INFO: Waiting up to 10m0s for PersistentVolume pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1 to get deleted
Apr 18 14:29:24.935: INFO: PersistentVolume pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1 found and phase=Bound (53.578032ms)
... skipping 23 lines ...
STEP: Collecting events from namespace "azurefile-2888".
STEP: Found 6 events.
Apr 18 14:31:06.201: INFO: At 2022-04-18 14:24:22 +0000 UTC - event for pvc-5chwj: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-2888/pvc-5chwj"
Apr 18 14:31:06.201: INFO: At 2022-04-18 14:24:22 +0000 UTC - event for pvc-5chwj: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 14:31:06.201: INFO: At 2022-04-18 14:24:22 +0000 UTC - event for pvc-5chwj: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1
Apr 18 14:31:06.201: INFO: At 2022-04-18 14:24:24 +0000 UTC - event for azurefile-volume-tester-bzd5q: {default-scheduler } Scheduled: Successfully assigned azurefile-2888/azurefile-volume-tester-bzd5q to capz-c79c-9hwfc
Apr 18 14:31:06.201: INFO: At 2022-04-18 14:24:26 +0000 UTC - event for azurefile-volume-tester-bzd5q: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-927f11b3-6d93-493f-a921-66fedf4bd0f1\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 14:31:06.201: INFO: At 2022-04-18 14:26:27 +0000 UTC - event for azurefile-volume-tester-bzd5q: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1]: timed out waiting for the condition
Apr 18 14:31:06.253: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 14:31:06.253: INFO: 
Apr 18 14:31:06.319: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 14:31:06.375: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 7727 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 14:29:21 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 14:29:21 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 14:29:21 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 14:29:21 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 113 lines ...
• Failure [407.553 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:185

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

... skipping 30 lines ...
Apr 18 14:31:28.020: INFO: PersistentVolumeClaim pvc-s5kkw found but phase is Pending instead of Bound.
Apr 18 14:31:30.073: INFO: PersistentVolumeClaim pvc-s5kkw found and phase=Bound (20.595354062s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with an error
Apr 18 14:31:30.235: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-djx6b" in namespace "azurefile-156" to be "Error status code"
Apr 18 14:31:30.288: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Pending", Reason="", readiness=false. Elapsed: 53.087777ms
Apr 18 14:31:32.342: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Pending", Reason="", readiness=false. Elapsed: 2.106900286s
Apr 18 14:31:34.397: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Pending", Reason="", readiness=false. Elapsed: 4.161997421s
Apr 18 14:31:36.452: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Pending", Reason="", readiness=false. Elapsed: 6.217259521s
Apr 18 14:31:38.508: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Pending", Reason="", readiness=false. Elapsed: 8.272634263s
Apr 18 14:31:40.564: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Pending", Reason="", readiness=false. Elapsed: 10.32878237s
Apr 18 14:31:42.620: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Running", Reason="", readiness=true. Elapsed: 12.384585067s
Apr 18 14:31:44.675: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Running", Reason="", readiness=true. Elapsed: 14.440250795s
Apr 18 14:31:46.731: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Running", Reason="", readiness=true. Elapsed: 16.495725651s
Apr 18 14:31:48.787: INFO: Pod "azurefile-volume-tester-djx6b": Phase="Failed", Reason="", readiness=false. Elapsed: 18.551398674s
STEP: Saw pod failure
Apr 18 14:31:48.787: INFO: Pod "azurefile-volume-tester-djx6b" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Apr 18 14:31:48.852: INFO: deleting Pod "azurefile-156"/"azurefile-volume-tester-djx6b"
Apr 18 14:31:48.910: INFO: Pod azurefile-volume-tester-djx6b 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 198 lines ...
Apr 18 14:36:51.768: 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-fstrm-5999c8bcc8\" is progressing."}}, CollisionCount:(*int32)(nil)}
Apr 18 14:36:53.767: 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-fstrm-5999c8bcc8\" is progressing."}}, CollisionCount:(*int32)(nil)}
Apr 18 14:36:55.768: 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-fstrm-5999c8bcc8\" is progressing."}}, CollisionCount:(*int32)(nil)}
Apr 18 14:36:57.767: 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-fstrm-5999c8bcc8\" is progressing."}}, CollisionCount:(*int32)(nil)}
Apr 18 14:36:57.820: 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-fstrm-5999c8bcc8\" is progressing."}}, CollisionCount:(*int32)(nil)}
Apr 18 14:36:57.821: INFO: deleting Deployment "azurefile-1563"/"azurefile-volume-tester-fstrm"
Apr 18 14:36:57.821: INFO: Error getting logs for pod : resource name may not be empty
Apr 18 14:36:57.876: INFO: deleting PVC "azurefile-1563"/"pvc-6bhkc"
Apr 18 14:36:57.876: INFO: Deleting PersistentVolumeClaim "pvc-6bhkc"
STEP: waiting for claim's PV "pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb" to be deleted
Apr 18 14:36:58.041: INFO: Waiting up to 10m0s for PersistentVolume pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb to get deleted
Apr 18 14:36:58.095: INFO: PersistentVolume pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb found and phase=Bound (53.661281ms)
Apr 18 14:37:03.149: INFO: PersistentVolume pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb found and phase=Bound (5.108511488s)
... skipping 24 lines ...
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:31:55 +0000 UTC - event for pvc-6bhkc: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:31:55 +0000 UTC - event for pvc-6bhkc: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:31:55 +0000 UTC - event for pvc-6bhkc: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-1563/pvc-6bhkc"
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:31:57 +0000 UTC - event for azurefile-volume-tester-fstrm: {deployment-controller } ScalingReplicaSet: Scaled up replica set azurefile-volume-tester-fstrm-5999c8bcc8 to 1
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:31:57 +0000 UTC - event for azurefile-volume-tester-fstrm-5999c8bcc8: {replicaset-controller } SuccessfulCreate: Created pod: azurefile-volume-tester-fstrm-5999c8bcc8-49fjf
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:31:57 +0000 UTC - event for azurefile-volume-tester-fstrm-5999c8bcc8-49fjf: {default-scheduler } Scheduled: Successfully assigned azurefile-1563/azurefile-volume-tester-fstrm-5999c8bcc8-49fjf to capz-c79c-9hwfc
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:32:00 +0000 UTC - event for azurefile-volume-tester-fstrm-5999c8bcc8-49fjf: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-26eddf84-8aee-4c62-bd74-38be363ccdbb\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 14:38:39.352: INFO: At 2022-04-18 14:34:00 +0000 UTC - event for azurefile-volume-tester-fstrm-5999c8bcc8-49fjf: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1 kube-api-access-q2dbw]: timed out waiting for the condition
Apr 18 14:38:39.406: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 14:38:39.406: INFO: 
Apr 18 14:38:39.474: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 14:38:39.530: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 8587 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 14:34:27 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 14:34:27 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 14:34:27 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 14:34:27 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 113 lines ...
• Failure [407.281 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:271

  Unexpected error:
      <*errors.errorString | 0xc000ba33c0>: {
          s: "error waiting for deployment \"azurefile-volume-tester-fstrm\" 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:\"MinimumReplicasUnavailable\", Message:\"Deployment does not have minimum availability.\"}, v1.DeploymentCondition{Type:\"Progressing\", Status:\"True\", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:\"ReplicaSetUpdated\", Message:\"ReplicaSet \\\"azurefile-volume-tester-fstrm-5999c8bcc8\\\" is progressing.\"}}, CollisionCount:(*int32)(nil)}",
      }
      error waiting for deployment "azurefile-volume-tester-fstrm" 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:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), LastTransitionTime:time.Date(2022, time.April, 18, 14, 31, 57, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-fstrm-5999c8bcc8\" 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 107 lines ...
Apr 18 14:39:14.037: INFO: PersistentVolumeClaim pvc-5tl4m found but phase is Pending instead of Bound.
Apr 18 14:39:16.092: INFO: PersistentVolumeClaim pvc-5tl4m found and phase=Bound (2.108433133s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:39:16.255: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7zzzc" in namespace "azurefile-2546" to be "Succeeded or Failed"
Apr 18 14:39:16.308: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 53.317644ms
Apr 18 14:39:18.362: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107647473s
Apr 18 14:39:20.418: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.16324403s
Apr 18 14:39:22.473: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218464208s
Apr 18 14:39:24.527: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.272715081s
Apr 18 14:39:26.583: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.328310431s
... skipping 427 lines ...
Apr 18 14:54:06.116: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.861587724s
Apr 18 14:54:08.171: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.91660679s
Apr 18 14:54:10.226: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.971231228s
Apr 18 14:54:12.280: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.025389326s
Apr 18 14:54:14.334: INFO: Pod "azurefile-volume-tester-7zzzc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.079712559s
Apr 18 14:54:16.335: INFO: deleting Pod "azurefile-2546"/"azurefile-volume-tester-7zzzc"
Apr 18 14:54:16.400: INFO: Error getting logs for pod azurefile-volume-tester-7zzzc: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-7zzzc)
STEP: Deleting pod azurefile-volume-tester-7zzzc in namespace azurefile-2546
Apr 18 14:54:16.458: INFO: deleting PVC "azurefile-2546"/"pvc-5tl4m"
Apr 18 14:54:16.459: INFO: Deleting PersistentVolumeClaim "pvc-5tl4m"
STEP: waiting for claim's PV "pvc-b517450b-7131-456e-be66-984e532e5782" to be deleted
Apr 18 14:54:16.623: INFO: Waiting up to 10m0s for PersistentVolume pvc-b517450b-7131-456e-be66-984e532e5782 to get deleted
Apr 18 14:54:16.677: INFO: PersistentVolume pvc-b517450b-7131-456e-be66-984e532e5782 found and phase=Bound (54.055089ms)
... skipping 11 lines ...
STEP: Collecting events from namespace "azurefile-2546".
STEP: Found 6 events.
Apr 18 14:54:57.289: INFO: At 2022-04-18 14:39:13 +0000 UTC - event for pvc-5tl4m: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-2546/pvc-5tl4m"
Apr 18 14:54:57.289: INFO: At 2022-04-18 14:39:13 +0000 UTC - event for pvc-5tl4m: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 14:54:57.289: INFO: At 2022-04-18 14:39:14 +0000 UTC - event for pvc-5tl4m: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-b517450b-7131-456e-be66-984e532e5782
Apr 18 14:54:57.289: INFO: At 2022-04-18 14:39:16 +0000 UTC - event for azurefile-volume-tester-7zzzc: {default-scheduler } Scheduled: Successfully assigned azurefile-2546/azurefile-volume-tester-7zzzc to capz-c79c-9hwfc
Apr 18 14:54:57.289: INFO: At 2022-04-18 14:39:18 +0000 UTC - event for azurefile-volume-tester-7zzzc: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-b517450b-7131-456e-be66-984e532e5782" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-b517450b-7131-456e-be66-984e532e5782#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-b517450b-7131-456e-be66-984e532e5782" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-b517450b-7131-456e-be66-984e532e5782\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 14:54:57.289: INFO: At 2022-04-18 14:41:19 +0000 UTC - event for azurefile-volume-tester-7zzzc: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1]: timed out waiting for the condition
Apr 18 14:54:57.342: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 14:54:57.342: INFO: 
Apr 18 14:54:57.409: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 14:54:57.465: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 11687 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 14:54:51 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 14:54:51 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 14:54:51 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 14:54:51 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 113 lines ...
• Failure [946.540 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:356

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

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:691
------------------------------
Dynamic Provisioning 
  should create a vhd disk volume on demand [kubernetes.io/azure-file] [file.csi.azure.com][disk]
... skipping 280 lines ...
Apr 18 14:55:19.775: INFO: PersistentVolumeClaim pvc-n7vtt found but phase is Pending instead of Bound.
Apr 18 14:55:21.829: INFO: PersistentVolumeClaim pvc-n7vtt found and phase=Bound (2.107848262s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 14:55:21.994: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-cqfqs" in namespace "azurefile-9183" to be "Succeeded or Failed"
Apr 18 14:55:22.052: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 57.912525ms
Apr 18 14:55:24.109: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.115307187s
Apr 18 14:55:26.164: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 4.170592295s
Apr 18 14:55:28.220: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 6.226168749s
Apr 18 14:55:30.276: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 8.282469852s
Apr 18 14:55:32.333: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 10.338936536s
... skipping 427 lines ...
Apr 18 15:10:12.951: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.957247965s
Apr 18 15:10:15.007: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.013155926s
Apr 18 15:10:17.063: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 14m55.069363105s
Apr 18 15:10:19.120: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.125766948s
Apr 18 15:10:21.176: INFO: Pod "azurefile-volume-tester-cqfqs": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.182362325s
Apr 18 15:10:23.178: INFO: deleting Pod "azurefile-9183"/"azurefile-volume-tester-cqfqs"
Apr 18 15:10:23.245: INFO: Error getting logs for pod azurefile-volume-tester-cqfqs: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-cqfqs)
STEP: Deleting pod azurefile-volume-tester-cqfqs in namespace azurefile-9183
Apr 18 15:10:23.301: INFO: deleting PVC "azurefile-9183"/"pvc-n7vtt"
Apr 18 15:10:23.301: INFO: Deleting PersistentVolumeClaim "pvc-n7vtt"
STEP: waiting for claim's PV "pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c" to be deleted
Apr 18 15:10:23.466: INFO: Waiting up to 10m0s for PersistentVolume pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c to get deleted
Apr 18 15:10:23.520: INFO: PersistentVolume pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c found and phase=Bound (53.878912ms)
... skipping 69 lines ...
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:17 +0000 UTC - event for pvc-5pkpb: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:17 +0000 UTC - event for pvc-5pkpb: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-cfd32c7e-190f-4b8d-8ee9-c51627951c3a
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:19 +0000 UTC - event for pvc-n7vtt: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-9183/pvc-n7vtt"
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:19 +0000 UTC - event for pvc-n7vtt: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:19 +0000 UTC - event for pvc-n7vtt: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:21 +0000 UTC - event for azurefile-volume-tester-cqfqs: {default-scheduler } Scheduled: Successfully assigned azurefile-9183/azurefile-volume-tester-cqfqs to capz-c79c-9hwfc
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:27 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-ccf39680-b0ab-4ded-8819-236ef178efde" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-ccf39680-b0ab-4ded-8819-236ef178efde#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-ccf39680-b0ab-4ded-8819-236ef178efde" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-ccf39680-b0ab-4ded-8819-236ef178efde\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:27 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-f11ec7d7-176d-4ac7-b2ca-640095f6eeb4" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-f11ec7d7-176d-4ac7-b2ca-640095f6eeb4#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-f11ec7d7-176d-4ac7-b2ca-640095f6eeb4" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-f11ec7d7-176d-4ac7-b2ca-640095f6eeb4\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:27 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-d71f665b-03d4-41c6-8d22-15b7e7b9c1fc" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-d71f665b-03d4-41c6-8d22-15b7e7b9c1fc#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-d71f665b-03d4-41c6-8d22-15b7e7b9c1fc" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-d71f665b-03d4-41c6-8d22-15b7e7b9c1fc\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:27 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-60b7710c-6f96-4803-9f7a-5abed6ab44ac" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-60b7710c-6f96-4803-9f7a-5abed6ab44ac#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-60b7710c-6f96-4803-9f7a-5abed6ab44ac" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-60b7710c-6f96-4803-9f7a-5abed6ab44ac\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:28 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-cfd32c7e-190f-4b8d-8ee9-c51627951c3a" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-cfd32c7e-190f-4b8d-8ee9-c51627951c3a#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-cfd32c7e-190f-4b8d-8ee9-c51627951c3a" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-cfd32c7e-190f-4b8d-8ee9-c51627951c3a\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:55:28 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-8082c1cc-e8f5-4845-a14c-1d637bf8a01c\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:11:20.952: INFO: At 2022-04-18 14:57:24 +0000 UTC - event for azurefile-volume-tester-cqfqs: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1 test-volume-2 test-volume-3 test-volume-4 test-volume-5 test-volume-6], unattached volumes=[test-volume-1 test-volume-2 test-volume-3 test-volume-4 test-volume-5 test-volume-6]: timed out waiting for the condition
Apr 18 15:11:21.005: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 15:11:21.005: INFO: 
Apr 18 15:11:21.073: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 15:11:21.129: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 14110 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 15:10:09 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 15:10:09 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 15:10:09 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 15:10:09 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
... skipping 113 lines ...
• Failure [976.276 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:617

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

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:691
------------------------------
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 33 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 15:11:25 Check successfully
Apr 18 15:11:25.274: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 15:11:25 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 15:11:25 got output: azure-storage-account-f386faeae73df489e95595f-secret
, error: <nil>
2022/04/18 15:11:25 got storage account secret name: azure-storage-account-f386faeae73df489e95595f-secret
STEP: setting up the StorageClass
STEP: creating a StorageClass 
STEP: setting up the PVC and PV
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
... skipping 145 lines ...
Apr 18 15:16:21.609: INFO: PersistentVolumeClaim pvc-8h8c2 found but phase is Pending instead of Bound.
Apr 18 15:16:23.664: INFO: PersistentVolumeClaim pvc-8h8c2 found but phase is Pending instead of Bound.
STEP: Collecting events from namespace "azurefile-1968".
STEP: Found 11 events.
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:25 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-1968/pvc-8h8c2"
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:25 +0000 UTC - event for pvc-8h8c2: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:25 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:11:24 GMT, RequestId=dc902c30-401a-00a7-6236-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:26 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:11:25 GMT, RequestId=dc902c34-401a-00a7-6336-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:28 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:11:27 GMT, RequestId=dc902c3c-401a-00a7-6636-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:32 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:11:31 GMT, RequestId=dc902c42-401a-00a7-6a36-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:40 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:11:39 GMT, RequestId=dc902c5c-401a-00a7-7c36-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:11:56 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:11:55 GMT, RequestId=dc902ca8-401a-00a7-1936-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:12:28 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:12:27 GMT, RequestId=dc902d10-401a-00a7-3c36-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:13:32 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:13:31 GMT, RequestId=dc902dc7-401a-00a7-7a36-53d8c8000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.722: INFO: At 2022-04-18 15:15:40 +0000 UTC - event for pvc-8h8c2: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningFailed: failed to provision volume with StorageClass "azurefile-1968-file.csi.azure.com-dynamic-sc-8d9j5": rpc error: code = Internal desc = storage: service returned error: StatusCode=403, ErrorCode=403 This request is not authorized to perform this operation., ErrorMessage=no response body was available for error status code, RequestInitiated=Mon, 18 Apr 2022 15:15:40 GMT, RequestId=49ef61f5-201a-0052-0f37-53fcd9000000, API Version=, QueryParameterName=, QueryParameterValue=
Apr 18 15:16:25.776: INFO: POD  NODE  PHASE  GRACE  CONDITIONS
Apr 18 15:16:25.776: INFO: 
Apr 18 15:16:25.844: INFO: 
Logging node info for node capz-c79c-9hwfc
Apr 18 15:16:25.901: INFO: Node Info: &Node{ObjectMeta:{capz-c79c-9hwfc    a673e34c-c89b-48d0-8251-bde142afeeea 14986 0 2022-04-18 13:48:10 +0000 UTC <nil> <nil> map[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:0 kubernetes.io/arch:amd64 kubernetes.io/hostname:capz-c79c-9hwfc kubernetes.io/os:windows node.kubernetes.io/instance-type:Standard_D4s_v3 node.kubernetes.io/windows-build:10.0.20348 topology.kubernetes.io/region:westus2 topology.kubernetes.io/zone:0] map[cluster.x-k8s.io/cluster-name:capz-c79crl cluster.x-k8s.io/cluster-namespace:default cluster.x-k8s.io/machine:capz-c79crl-md-win-57c8cb5f68-zs6n9 cluster.x-k8s.io/owner-kind:MachineSet cluster.x-k8s.io/owner-name:capz-c79crl-md-win-57c8cb5f68 csi.volume.kubernetes.io/nodeid:{"file.csi.azure.com":"capz-c79c-9hwfc"} kubeadm.alpha.kubernetes.io/cri-socket:npipe:////./pipe/containerd-containerd node.alpha.kubernetes.io/ttl:0 projectcalico.org/IPv4Address:10.1.0.6/16 projectcalico.org/IPv4VXLANTunnelAddr:192.168.100.129 projectcalico.org/VXLANTunnelMACAddr:00:15:5d:f0:66:da volumes.kubernetes.io/controller-managed-attach-detach:true] [] []  [{Go-http-client Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubeadm.alpha.kubernetes.io/cri-socket":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"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.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:node.kubernetes.io/windows-build":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}}} } {kube-controller-manager Update v1 2022-04-18 13:48:11 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}}} } {manager Update v1 2022-04-18 13:48:25 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:cluster.x-k8s.io/cluster-name":{},"f:cluster.x-k8s.io/cluster-namespace":{},"f:cluster.x-k8s.io/machine":{},"f:cluster.x-k8s.io/owner-kind":{},"f:cluster.x-k8s.io/owner-name":{}}}} } {calico-node.exe Update v1 2022-04-18 13:49:53 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:projectcalico.org/IPv4Address":{},"f:projectcalico.org/IPv4VXLANTunnelAddr":{},"f:projectcalico.org/VXLANTunnelMACAddr":{}}}} status} {Go-http-client Update v1 2022-04-18 13:53:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:csi.volume.kubernetes.io/nodeid":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"DiskPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"MemoryPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"PIDPressure\"}":{"f:lastHeartbeatTime":{}},"k:{\"type\":\"Ready\"}":{"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{}}},"f:images":{}}} status}]},Spec:NodeSpec{PodCIDR:,DoNotUseExternalID:,ProviderID:azure:///subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-c79crl/providers/Microsoft.Compute/virtualMachines/capz-c79c-9hwfc,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: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-azure-disk: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{123221307598 0} {<nil>} 123221307598 DecimalSI},memory: {{17074540544 0} {<nil>} 16674356Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-04-18 15:15:16 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-04-18 15:15:16 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-04-18 15:15:16 +0000 UTC,LastTransitionTime:2022-04-18 13:48:10 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-04-18 15:15:16 +0000 UTC,LastTransitionTime:2022-04-18 13:49:21 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status,},},Addresses:[]NodeAddress{NodeAddress{Type:Hostname,Address:capz-c79c-9hwfc,},NodeAddress{Type:InternalIP,Address:10.1.0.6,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:capz-c79c-9hwfc,SystemUUID:FAF80233-2A21-4EC1-B111-7680544FBFD5,BootID:,KernelVersion:10.0.20348.405,OSImage:Windows Server 2022 Datacenter,ContainerRuntimeVersion:containerd://1.6.1,KubeletVersion:v1.23.5,KubeProxyVersion:v1.23.5,OperatingSystem:windows,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[mcr.microsoft.com/windows/servercore@sha256:378d85bd8e7388a777d25009f8523d1e95a5f544f131eaada83171045d5b2c1e mcr.microsoft.com/windows/servercore:ltsc2022],SizeBytes:2226956779,},ContainerImage{Names:[docker.io/sigwindowstools/calico-install@sha256:141afecd724eb757ee41593cc73f35fb19a2ce13cad73179cf3b1cef81a637d1 docker.io/sigwindowstools/calico-install:v3.22.1-hostprocess],SizeBytes:148096127,},ContainerImage{Names:[capzci.azurecr.io/azurefile-csi@sha256:4de4ce0615b7baa1c61f09c34929bfeb58103425f19f85ef53dc971478ee6221 capzci.azurecr.io/azurefile-csi:e2e-e26e7de71127b97f66755f201ba28bd77d2fa10e],SizeBytes:130280733,},ContainerImage{Names:[docker.io/sigwindowstools/calico-node@sha256:b8e6e2f190e58d6b61b7f2a19b0e2e17a377e5b9d7b9528e9b7953d9f9ab59bb docker.io/sigwindowstools/calico-node:v3.22.1-hostprocess],SizeBytes:128793648,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar@sha256:dbec3a8166686b09b242176ab5b99e993da4126438bbce68147c3fd654f35662 mcr.microsoft.com/oss/kubernetes-csi/csi-node-driver-registrar:v2.4.0],SizeBytes:125554391,},ContainerImage{Names:[mcr.microsoft.com/oss/kubernetes-csi/livenessprobe@sha256:c96a6255c42766f6b8bb1a7cda02b0060ab1b20b2e2dafcc64ec09e7646745a6 mcr.microsoft.com/oss/kubernetes-csi/livenessprobe:v2.5.0],SizeBytes:124471446,},ContainerImage{Names:[ghcr.io/kubernetes-sigs/sig-windows/csi-proxy@sha256:96b4144986319a747ba599892454be2737aae6005d96b8e13ed481321ac3afba ghcr.io/kubernetes-sigs/sig-windows/csi-proxy:v1.0.2],SizeBytes:123925937,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:3d380ca8864549e74af4b29c10f9cb0956236dfb01c40ca076fb6c37253234db k8s.gcr.io/pause:3.6],SizeBytes:119397646,},ContainerImage{Names:[docker.io/sigwindowstools/kube-proxy@sha256:0f8a44b795d1824358f24cc56f0024d18a39ae044656686596d8b7fa6d78e1fa docker.io/sigwindowstools/kube-proxy:v1.23.5-calico-hostprocess],SizeBytes:116337721,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},}
Apr 18 15:16:25.901: INFO: 
... skipping 112 lines ...
• Failure [303.594 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:676

  Unexpected error:
      <*errors.errorString | 0xc000802de0>: {
          s: "PersistentVolumeClaims [pvc-8h8c2] not all in phase Bound within 5m0s",
      }
      PersistentVolumeClaims [pvc-8h8c2] not all in phase Bound within 5m0s
  occurred

... skipping 31 lines ...
Apr 18 15:16:49.594: INFO: PersistentVolumeClaim pvc-cbr2c found and phase=Bound (20.599067372s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: sleep 1s waiting for volume ready in windows-2022
STEP: checking that the pods command exits with no error
Apr 18 15:16:50.760: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qlg87" in namespace "azurefile-4657" to be "Succeeded or Failed"
Apr 18 15:16:50.814: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Pending", Reason="", readiness=false. Elapsed: 53.969359ms
Apr 18 15:16:52.869: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Pending", Reason="", readiness=false. Elapsed: 2.109138187s
Apr 18 15:16:54.924: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Pending", Reason="", readiness=false. Elapsed: 4.164404702s
Apr 18 15:16:56.980: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220436352s
Apr 18 15:16:59.037: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Pending", Reason="", readiness=false. Elapsed: 8.276950406s
Apr 18 15:17:01.093: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Pending", Reason="", readiness=false. Elapsed: 10.333343618s
Apr 18 15:17:03.149: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Running", Reason="", readiness=true. Elapsed: 12.388642043s
Apr 18 15:17:05.204: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Running", Reason="", readiness=true. Elapsed: 14.444582247s
Apr 18 15:17:07.261: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Running", Reason="", readiness=true. Elapsed: 16.501105607s
Apr 18 15:17:09.317: INFO: Pod "azurefile-volume-tester-qlg87": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.557257301s
STEP: Saw pod success
Apr 18 15:17:09.317: INFO: Pod "azurefile-volume-tester-qlg87" satisfied condition "Succeeded or Failed"
Apr 18 15:17:09.317: INFO: deleting Pod "azurefile-4657"/"azurefile-volume-tester-qlg87"
Apr 18 15:17:09.380: INFO: Pod azurefile-volume-tester-qlg87 has the following logs: hello world

STEP: Deleting pod azurefile-volume-tester-qlg87 in namespace azurefile-4657
Apr 18 15:17:09.441: INFO: deleting PVC "azurefile-4657"/"pvc-cbr2c"
Apr 18 15:17:09.441: INFO: Deleting PersistentVolumeClaim "pvc-cbr2c"
... skipping 331 lines ...
I0418 15:27:09.964320   36728 testsuites.go:630] 0/1 replicas in the StatefulSet are ready
I0418 15:27:11.964712   36728 testsuites.go:630] 0/1 replicas in the StatefulSet are ready
I0418 15:27:13.964186   36728 testsuites.go:630] 0/1 replicas in the StatefulSet are ready
I0418 15:27:15.963877   36728 testsuites.go:630] 0/1 replicas in the StatefulSet are ready
I0418 15:27:16.017862   36728 testsuites.go:630] 0/1 replicas in the StatefulSet are ready
Apr 18 15:27:16.018: INFO: deleting StatefulSet "azurefile-1359"/"azurefile-volume-tester-n6ncv"
Apr 18 15:27:16.018: INFO: Error getting logs for pod : resource name may not be empty
Apr 18 15:27:16.073: INFO: deleting StorageClass azurefile-1359-file.csi.azure.com-dynamic-sc-nff96
STEP: Collecting events from namespace "azurefile-1359".
STEP: Found 10 events.
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:15 +0000 UTC - event for azurefile-volume-tester-n6ncv: {statefulset-controller } SuccessfulCreate: create Pod azurefile-volume-tester-n6ncv-0 in StatefulSet azurefile-volume-tester-n6ncv successful
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:15 +0000 UTC - event for azurefile-volume-tester-n6ncv: {statefulset-controller } SuccessfulCreate: create Claim pvc-azurefile-volume-tester-n6ncv-0 Pod azurefile-volume-tester-n6ncv-0 in StatefulSet azurefile-volume-tester-n6ncv success
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:15 +0000 UTC - event for azurefile-volume-tester-n6ncv-0: {default-scheduler } FailedScheduling: 0/5 nodes are available: 5 pod has unbound immediate PersistentVolumeClaims.
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:15 +0000 UTC - event for pvc-azurefile-volume-tester-n6ncv-0: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } Provisioning: External provisioner is provisioning volume for claim "azurefile-1359/pvc-azurefile-volume-tester-n6ncv-0"
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:15 +0000 UTC - event for pvc-azurefile-volume-tester-n6ncv-0: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "file.csi.azure.com" or manually created by system administrator
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:16 +0000 UTC - event for azurefile-volume-tester-n6ncv-0: {default-scheduler } Scheduled: Successfully assigned azurefile-1359/azurefile-volume-tester-n6ncv-0 to capz-c79c-9hwfc
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:16 +0000 UTC - event for pvc-azurefile-volume-tester-n6ncv-0: {file.csi.azure.com_capz-c79crl-md-0-cjk22_8bfaaf94-226a-4da9-a68e-e10262705201 } ProvisioningSucceeded: Successfully provisioned volume pvc-c2bcd091-1441-439f-9add-7be2cc9bbe1b
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:17:19 +0000 UTC - event for azurefile-volume-tester-n6ncv-0: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.MountDevice failed for volume "pvc-c2bcd091-1441-439f-9add-7be2cc9bbe1b" : rpc error: code = Internal desc = volume(capz-c79crl#f386faeae73df489e95595f#pvc-c2bcd091-1441-439f-9add-7be2cc9bbe1b#) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\pvc-c2bcd091-1441-439f-9add-7be2cc9bbe1b" on "\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-c2bcd091-1441-439f-9add-7be2cc9bbe1b\\globalmount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:19:19 +0000 UTC - event for azurefile-volume-tester-n6ncv-0: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[pvc], unattached volumes=[pvc kube-api-access-pql8g]: timed out waiting for the condition
Apr 18 15:27:16.184: INFO: At 2022-04-18 15:21:36 +0000 UTC - event for azurefile-volume-tester-n6ncv-0: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[pvc], unattached volumes=[kube-api-access-pql8g pvc]: timed out waiting for the condition
Apr 18 15:27:16.239: INFO: POD                              NODE             PHASE    GRACE  CONDITIONS
Apr 18 15:27:16.239: INFO: azurefile-volume-tester-n6ncv-0  capz-c79c-9hwfc  Pending  30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:17:16 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:17:16 +0000 UTC ContainersNotReady containers with unready status: [volume-tester]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:17:16 +0000 UTC ContainersNotReady containers with unready status: [volume-tester]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:17:16 +0000 UTC  }]
Apr 18 15:27:16.239: INFO: 
Apr 18 15:27:16.306: INFO: 
... skipping 117 lines ...
• Failure [603.630 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create a statefulset object, write and read to it, delete the pod and write and read to it again [file.csi.azure.com] [It]
  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:777

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

... skipping 11 lines ...
check the driver pods if restarts ...
======================================================================================
2022/04/18 15:27:19 Check successfully
Apr 18 15:27:19.608: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
2022/04/18 15:27:19 run script: test/utils/get_storage_account_secret_name.sh
2022/04/18 15:27:19 got output: azure-storage-account-f386faeae73df489e95595f-secret
, error: <nil>
2022/04/18 15:27:19 got storage account secret name: azure-storage-account-f386faeae73df489e95595f-secret
STEP: Successfully provisioned AzureFile volume: "capz-c79crl#f386faeae73df489e95595f#csi-inline-smb-volume##csi-inline-smb-volume"

STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 15:27:21.166: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-rcb2z" in namespace "azurefile-4162" to be "Succeeded or Failed"
Apr 18 15:27:21.220: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 54.616451ms
Apr 18 15:27:23.276: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 2.1099775s
Apr 18 15:27:25.330: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 4.164674073s
Apr 18 15:27:27.385: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6.21942429s
Apr 18 15:27:29.440: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 8.273979207s
Apr 18 15:27:31.494: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 10.328534602s
... skipping 187 lines ...
Apr 18 15:33:57.828: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m36.662109291s
Apr 18 15:33:59.882: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m38.716805876s
Apr 18 15:34:01.937: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m40.771121669s
Apr 18 15:34:03.992: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m42.826184601s
Apr 18 15:34:06.046: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m44.880845776s
Apr 18 15:34:08.101: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m46.935018743s
{"component":"entrypoint","file":"k8s.io/test-infra/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":"2022-04-18T15:34:09Z"}
++ early_exit_handler
++ '[' -n 157 ']'
++ kill -TERM 157
++ cleanup_dind
++ [[ true == \t\r\u\e ]]
++ echo 'Cleaning up after docker'
Cleaning up after docker
++ docker ps -aq
++ xargs -r docker rm -f
make: Nothing to be done for 'kubectl'.
Apr 18 15:34:10.155: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m48.989241731s
================ DUMPING LOGS FOR MANAGEMENT CLUSTER ================
ERROR: failed to get cluster internal kubeconfig: command "docker exec --privileged capz-control-plane cat /etc/kubernetes/admin.conf" failed with error: exit status 1

Command Output: Error response from daemon: Container b76a806424a23e507688b086c31b8e3956bdeda5a53f5df1f014164ce99c0e4e is not running
b76a806424a2
502e05325626
++ service docker stop
Stopping Docker: dockerError from server (NotFound): error when deleting "./scripts/../hack/log/../../hack/log/log-dump-daemonset.yaml": daemonsets.apps "log-dump-node" not found
Error from server (NotFound): error when deleting "./scripts/../hack/log/../../hack/log/log-dump-daemonset-windows.yaml": daemonsets.apps "log-dump-node-windows" not found
================ REDACTING LOGS ================
All sensitive variables are redacted
The connection to the server 127.0.0.1:42023 was refused - did you specify the right host or port?
kind delete cluster --name=capz || true
Deleting cluster "capz" ...
ERROR: failed to delete cluster "capz": error listing nodes: failed to list clusters: command "docker ps -a --filter label=io.x-k8s.kind.cluster=capz --format '{{.Names}}'" failed with error: exit status 1

Command Output: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
kind delete cluster --name=capz-e2e || true
Deleting cluster "capz-e2e" ...
ERROR: failed to delete cluster "capz-e2e": error listing nodes: failed to list clusters: command "docker ps -a --filter label=io.x-k8s.kind.cluster=capz-e2e --format '{{.Names}}'" failed with error: exit status 1

Command Output: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
Apr 18 15:34:12.211: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m51.045510962s
Apr 18 15:34:14.266: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m53.099958916s
Apr 18 15:34:16.321: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m55.155144853s
Apr 18 15:34:18.375: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 6m57.209718489s
... skipping 240 lines ...
Apr 18 15:42:11.019: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.853078815s
Apr 18 15:42:13.073: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.90749672s
Apr 18 15:42:15.128: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.962805519s
Apr 18 15:42:17.183: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.016909044s
Apr 18 15:42:19.238: INFO: Pod "azurefile-volume-tester-rcb2z": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.072251786s
Apr 18 15:42:21.239: INFO: deleting Pod "azurefile-4162"/"azurefile-volume-tester-rcb2z"
Apr 18 15:42:21.316: INFO: Error getting logs for pod azurefile-volume-tester-rcb2z: the server rejected our request for an unknown reason (get pods azurefile-volume-tester-rcb2z)
STEP: Deleting pod azurefile-volume-tester-rcb2z in namespace azurefile-4162
STEP: Collecting events from namespace "azurefile-4162".
STEP: Found 3 events.
Apr 18 15:42:21.428: INFO: At 2022-04-18 15:27:21 +0000 UTC - event for azurefile-volume-tester-rcb2z: {default-scheduler } Scheduled: Successfully assigned azurefile-4162/azurefile-volume-tester-rcb2z to capz-c79c-9hwfc
Apr 18 15:42:21.428: INFO: At 2022-04-18 15:27:26 +0000 UTC - event for azurefile-volume-tester-rcb2z: {kubelet capz-c79c-9hwfc} FailedMount: MountVolume.SetUp failed for volume "test-volume-1" : rpc error: code = Internal desc = volume(csi-53c0396595359bbf3805e448bab1ef1c7c56f0c63fd9d467e5017d0fceebf49d) mount "\\\\f386faeae73df489e95595f.file.core.windows.net\\csi-inline-smb-volume" on "c:\\var\\lib\\kubelet\\pods\\a56a1712-e8d2-4a6b-a2c4-3aa93c4082ed\\volumes\\kubernetes.io~csi\\test-volume-1\\mount" failed with smb mapping failed with error: rpc error: code = Unknown desc = NewSmbGlobalMapping failed. output: "New-SmbGlobalMapping : Access is denied. \r\nAt line:1 char:190\r\n+ ... ser, $PWord;New-SmbGlobalMapping -RemotePath $Env:smbremotepath -Cred ...\r\n+                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\r\n    + CategoryInfo          : PermissionDenied: (MSFT_SmbGlobalMapping:ROOT/Microsoft/...mbGlobalMapping) [New-SmbGlob \r\n   alMapping], CimException\r\n    + FullyQualifiedErrorId : Windows System Error 5,New-SmbGlobalMapping\r\n \r\n", err: exit status 1
Apr 18 15:42:21.428: INFO: At 2022-04-18 15:29:24 +0000 UTC - event for azurefile-volume-tester-rcb2z: {kubelet capz-c79c-9hwfc} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume-1], unattached volumes=[test-volume-1]: timed out waiting for the condition
Apr 18 15:42:21.483: INFO: POD                            NODE             PHASE    GRACE  CONDITIONS
Apr 18 15:42:21.483: INFO: azurefile-volume-tester-rcb2z  capz-c79c-9hwfc  Pending  30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:27:21 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:27:21 +0000 UTC ContainersNotReady containers with unready status: [volume-tester]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:27:21 +0000 UTC ContainersNotReady containers with unready status: [volume-tester]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-04-18 15:27:21 +0000 UTC  }]
Apr 18 15:42:21.483: INFO: 
Apr 18 15:42:21.554: INFO: 
Logging node info for node capz-c79c-9hwfc
... skipping 116 lines ...
• Failure [905.224 seconds]
Dynamic Provisioning
/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:42
  should create an CSI inline volume [file.csi.azure.com] [It]
  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:813

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

  /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:691
------------------------------
Dynamic Provisioning 
  should create an inline volume by in-tree driver [kubernetes.io/azure-file]
... skipping 34 lines ...
======================================================================================
2022/04/18 15:42:25 Check successfully
Apr 18 15:42:25.765: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: creating secret smbcreds in namespace azurefile-5320
2022/04/18 15:42:25 run script: test/utils/get_smb_svc_public_ip.sh
2022/04/18 15:42:26 got output: <pending>
, error: <nil>
2022/04/18 15:42:26 use server on Windows: <pending>
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Apr 18 15:42:26.153: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-fqp7g" in namespace "azurefile-5320" to be "Succeeded or Failed"
Apr 18 15:42:26.207: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 53.741316ms
Apr 18 15:42:28.261: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.107961791s
Apr 18 15:42:30.315: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.162205274s
Apr 18 15:42:32.369: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.216568244s
Apr 18 15:42:34.424: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.271075283s
Apr 18 15:42:36.478: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.325537325s
... skipping 185 lines ...
Apr 18 15:48:58.712: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6m32.558993942s
Apr 18 15:49:00.766: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6m34.613227109s
Apr 18 15:49:02.821: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6m36.668391655s
Apr 18 15:49:04.876: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6m38.722879102s
Apr 18 15:49:06.930: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6m40.77740168s
Apr 18 15:49:08.985: INFO: Pod "azurefile-volume-tester-fqp7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6m42.831877064s
{"component":"entrypoint","file":"k8s.io/test-infra/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":"2022-04-18T15:49:09Z"}
{"component":"entrypoint","error":"os: process already finished","file":"k8s.io/test-infra/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":"2022-04-18T15:49:09Z"}