kubernetes-sigs/azurefile-csi-driver PR #1172 pull-azurefile-csi-driver-e2e-capz-windows-2019 #1619965933789384704
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | andyzhangx: fix: incorrect driver version in CSIDriver |
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 1h6m |
| Revision | 38e7f23c91488819c3ba76b2df5a19d34fb4b380 |
| Refs |
1172 |
... skipping 806 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 # Create customized cloud provider configs ./hack/create-custom-cloud-provider-config.sh make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' make[2]: Nothing to be done for 'kubectl'. ... skipping 221 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 181k 0 --:--:-- --:--:-- --:--:-- 181k Downloading https://get.helm.sh/helm-v3.11.0-linux-amd64.tar.gz Verifying checksum... Done. Preparing to install helm into /usr/local/bin helm installed into /usr/local/bin/helm docker pull capzci.azurecr.io/azurefile-csi:e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 || make container-all push-manifest Error response from daemon: manifest for capzci.azurecr.io/azurefile-csi:e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 not found: manifest unknown: manifest tagged by "e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296" is not found make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver' CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.driverVersion=e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=96a2ca02f36f8e1cb5b590f772c52ba00ac89296 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2023-01-30T08:05:06Z -s -w -extldflags '-static'" -mod vendor -o _output/amd64/azurefileplugin.exe ./pkg/azurefileplugin docker buildx rm container-builder || true ERROR: no builder "container-builder" found docker buildx create --use --name=container-builder container-builder # enable qemu for arm64 build # https://github.com/docker/buildx/issues/464#issuecomment-741507760 docker run --privileged --rm tonistiigi/binfmt --uninstall qemu-aarch64 Unable to find image 'tonistiigi/binfmt:latest' locally ... skipping 2555 lines ... image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.6.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 354 lines ... Jan 30 08:22:24.204: INFO: PersistentVolumeClaim pvc-7t4rj found but phase is Pending instead of Bound. Jan 30 08:22:26.314: INFO: PersistentVolumeClaim pvc-7t4rj found and phase=Bound (1m49.83035825s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:22:26.314[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:22:26.425[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:22:26.534[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:22:26.534[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:22:26.649[0m Jan 30 08:22:26.649: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lwpmj" in namespace "azurefile-2540" to be "Succeeded or Failed" Jan 30 08:22:26.758: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 108.351177ms Jan 30 08:22:28.868: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218781015s Jan 30 08:22:30.868: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219273265s Jan 30 08:22:32.876: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.226830242s Jan 30 08:22:34.867: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.217711431s Jan 30 08:22:36.874: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.225139674s ... skipping 77 lines ... Jan 30 08:25:12.873: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=true. Elapsed: 2m46.224232526s Jan 30 08:25:14.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=true. Elapsed: 2m48.225611693s Jan 30 08:25:16.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=true. Elapsed: 2m50.226011683s Jan 30 08:25:18.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=false. Elapsed: 2m52.226081333s Jan 30 08:25:20.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m54.225676361s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:25:20.875[0m Jan 30 08:25:20.875: INFO: Pod "azurefile-volume-tester-lwpmj" satisfied condition "Succeeded or Failed" Jan 30 08:25:20.875: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-lwpmj" Jan 30 08:25:21.006: INFO: Pod azurefile-volume-tester-lwpmj has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-lwpmj in namespace azurefile-2540 [38;5;243m01/30/23 08:25:21.006[0m Jan 30 08:25:21.231: INFO: deleting PVC "azurefile-2540"/"pvc-7t4rj" Jan 30 08:25:21.231: INFO: Deleting PersistentVolumeClaim "pvc-7t4rj" ... skipping 79 lines ... Jan 30 08:22:24.204: INFO: PersistentVolumeClaim pvc-7t4rj found but phase is Pending instead of Bound. Jan 30 08:22:26.314: INFO: PersistentVolumeClaim pvc-7t4rj found and phase=Bound (1m49.83035825s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:22:26.314[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:22:26.425[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:22:26.534[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:22:26.534[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:22:26.649[0m Jan 30 08:22:26.649: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lwpmj" in namespace "azurefile-2540" to be "Succeeded or Failed" Jan 30 08:22:26.758: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 108.351177ms Jan 30 08:22:28.868: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218781015s Jan 30 08:22:30.868: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219273265s Jan 30 08:22:32.876: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.226830242s Jan 30 08:22:34.867: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.217711431s Jan 30 08:22:36.874: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.225139674s ... skipping 77 lines ... Jan 30 08:25:12.873: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=true. Elapsed: 2m46.224232526s Jan 30 08:25:14.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=true. Elapsed: 2m48.225611693s Jan 30 08:25:16.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=true. Elapsed: 2m50.226011683s Jan 30 08:25:18.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Running", Reason="", readiness=false. Elapsed: 2m52.226081333s Jan 30 08:25:20.875: INFO: Pod "azurefile-volume-tester-lwpmj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m54.225676361s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:25:20.875[0m Jan 30 08:25:20.875: INFO: Pod "azurefile-volume-tester-lwpmj" satisfied condition "Succeeded or Failed" Jan 30 08:25:20.875: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-lwpmj" Jan 30 08:25:21.006: INFO: Pod azurefile-volume-tester-lwpmj has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-lwpmj in namespace azurefile-2540 [38;5;243m01/30/23 08:25:21.006[0m Jan 30 08:25:21.231: INFO: deleting PVC "azurefile-2540"/"pvc-7t4rj" Jan 30 08:25:21.231: INFO: Deleting PersistentVolumeClaim "pvc-7t4rj" ... skipping 41 lines ... Jan 30 08:25:54.201: INFO: PersistentVolumeClaim pvc-664k7 found but phase is Pending instead of Bound. Jan 30 08:25:56.310: INFO: PersistentVolumeClaim pvc-664k7 found and phase=Bound (27.522853395s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:25:56.31[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:25:56.418[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:25:56.526[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:25:56.526[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:25:56.638[0m Jan 30 08:25:56.638: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-cs4vd" in namespace "azurefile-4728" to be "Succeeded or Failed" Jan 30 08:25:56.750: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 112.189308ms Jan 30 08:25:58.860: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.221866496s Jan 30 08:26:00.867: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22914326s Jan 30 08:26:02.866: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.22805399s Jan 30 08:26:04.868: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 8.229622569s Jan 30 08:26:06.867: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 10.229082265s Jan 30 08:26:08.868: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Running", Reason="", readiness=true. Elapsed: 12.229644414s Jan 30 08:26:10.867: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Running", Reason="", readiness=true. Elapsed: 14.229372141s Jan 30 08:26:12.865: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Running", Reason="", readiness=false. Elapsed: 16.227583372s Jan 30 08:26:14.866: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.228246335s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:26:14.866[0m Jan 30 08:26:14.866: INFO: Pod "azurefile-volume-tester-cs4vd" satisfied condition "Succeeded or Failed" Jan 30 08:26:14.866: INFO: deleting Pod "azurefile-4728"/"azurefile-volume-tester-cs4vd" Jan 30 08:26:14.982: INFO: Pod azurefile-volume-tester-cs4vd has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-cs4vd in namespace azurefile-4728 [38;5;243m01/30/23 08:26:14.982[0m Jan 30 08:26:15.108: INFO: deleting PVC "azurefile-4728"/"pvc-664k7" Jan 30 08:26:15.108: INFO: Deleting PersistentVolumeClaim "pvc-664k7" ... skipping 40 lines ... Jan 30 08:25:54.201: INFO: PersistentVolumeClaim pvc-664k7 found but phase is Pending instead of Bound. Jan 30 08:25:56.310: INFO: PersistentVolumeClaim pvc-664k7 found and phase=Bound (27.522853395s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:25:56.31[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:25:56.418[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:25:56.526[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:25:56.526[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:25:56.638[0m Jan 30 08:25:56.638: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-cs4vd" in namespace "azurefile-4728" to be "Succeeded or Failed" Jan 30 08:25:56.750: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 112.189308ms Jan 30 08:25:58.860: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.221866496s Jan 30 08:26:00.867: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22914326s Jan 30 08:26:02.866: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.22805399s Jan 30 08:26:04.868: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 8.229622569s Jan 30 08:26:06.867: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Pending", Reason="", readiness=false. Elapsed: 10.229082265s Jan 30 08:26:08.868: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Running", Reason="", readiness=true. Elapsed: 12.229644414s Jan 30 08:26:10.867: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Running", Reason="", readiness=true. Elapsed: 14.229372141s Jan 30 08:26:12.865: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Running", Reason="", readiness=false. Elapsed: 16.227583372s Jan 30 08:26:14.866: INFO: Pod "azurefile-volume-tester-cs4vd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.228246335s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:26:14.866[0m Jan 30 08:26:14.866: INFO: Pod "azurefile-volume-tester-cs4vd" satisfied condition "Succeeded or Failed" Jan 30 08:26:14.866: INFO: deleting Pod "azurefile-4728"/"azurefile-volume-tester-cs4vd" Jan 30 08:26:14.982: INFO: Pod azurefile-volume-tester-cs4vd has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-cs4vd in namespace azurefile-4728 [38;5;243m01/30/23 08:26:14.982[0m Jan 30 08:26:15.108: INFO: deleting PVC "azurefile-4728"/"pvc-664k7" Jan 30 08:26:15.108: INFO: Deleting PersistentVolumeClaim "pvc-664k7" ... skipping 203 lines ... Jan 30 08:27:29.971: INFO: PersistentVolumeClaim pvc-gljzn found but phase is Pending instead of Bound. Jan 30 08:27:32.079: INFO: PersistentVolumeClaim pvc-gljzn found and phase=Bound (33.857521635s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:27:32.079[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:27:32.188[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:27:32.296[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:27:32.296[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m01/30/23 08:27:32.409[0m Jan 30 08:27:32.409: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lh7gp" in namespace "azurefile-2790" to be "Error status code" Jan 30 08:27:32.518: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 108.643665ms Jan 30 08:27:34.627: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217753426s Jan 30 08:27:36.634: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22459184s Jan 30 08:27:38.634: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224564932s Jan 30 08:27:40.637: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=true. Elapsed: 8.227889975s Jan 30 08:27:42.635: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=true. Elapsed: 10.2261614s Jan 30 08:27:44.636: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=true. Elapsed: 12.227010786s Jan 30 08:27:46.635: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=false. Elapsed: 14.225476866s Jan 30 08:27:48.633: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Failed", Reason="", readiness=false. Elapsed: 16.224136065s [1mSTEP:[0m Saw pod failure [38;5;243m01/30/23 08:27:48.634[0m Jan 30 08:27:48.634: INFO: Pod "azurefile-volume-tester-lh7gp" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/30/23 08:27:48.634[0m Jan 30 08:27:48.753: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-lh7gp" Jan 30 08:27:48.864: INFO: Pod azurefile-volume-tester-lh7gp 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 51 lines ... Jan 30 08:27:29.971: INFO: PersistentVolumeClaim pvc-gljzn found but phase is Pending instead of Bound. Jan 30 08:27:32.079: INFO: PersistentVolumeClaim pvc-gljzn found and phase=Bound (33.857521635s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:27:32.079[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:27:32.188[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:27:32.296[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:27:32.296[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m01/30/23 08:27:32.409[0m Jan 30 08:27:32.409: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-lh7gp" in namespace "azurefile-2790" to be "Error status code" Jan 30 08:27:32.518: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 108.643665ms Jan 30 08:27:34.627: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217753426s Jan 30 08:27:36.634: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22459184s Jan 30 08:27:38.634: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224564932s Jan 30 08:27:40.637: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=true. Elapsed: 8.227889975s Jan 30 08:27:42.635: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=true. Elapsed: 10.2261614s Jan 30 08:27:44.636: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=true. Elapsed: 12.227010786s Jan 30 08:27:46.635: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Running", Reason="", readiness=false. Elapsed: 14.225476866s Jan 30 08:27:48.633: INFO: Pod "azurefile-volume-tester-lh7gp": Phase="Failed", Reason="", readiness=false. Elapsed: 16.224136065s [1mSTEP:[0m Saw pod failure [38;5;243m01/30/23 08:27:48.634[0m Jan 30 08:27:48.634: INFO: Pod "azurefile-volume-tester-lh7gp" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/30/23 08:27:48.634[0m Jan 30 08:27:48.753: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-lh7gp" Jan 30 08:27:48.864: INFO: Pod azurefile-volume-tester-lh7gp 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 362 lines ... Jan 30 08:29:56.815: INFO: PersistentVolumeClaim pvc-cql2p found but phase is Pending instead of Bound. Jan 30 08:29:58.924: INFO: PersistentVolumeClaim pvc-cql2p found and phase=Bound (31.751004612s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:29:58.924[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:29:59.032[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:29:59.14[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:29:59.14[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:29:59.254[0m Jan 30 08:29:59.254: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4z4r5" in namespace "azurefile-4538" to be "Succeeded or Failed" Jan 30 08:29:59.362: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 107.781466ms Jan 30 08:30:01.471: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.216857858s Jan 30 08:30:03.479: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.224841073s Jan 30 08:30:05.484: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.229718248s Jan 30 08:30:07.478: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=true. Elapsed: 8.224480177s Jan 30 08:30:09.478: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=true. Elapsed: 10.224482687s Jan 30 08:30:11.482: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=true. Elapsed: 12.227752422s Jan 30 08:30:13.481: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=false. Elapsed: 14.227193071s Jan 30 08:30:15.479: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.225369348s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:30:15.479[0m Jan 30 08:30:15.479: INFO: Pod "azurefile-volume-tester-4z4r5" satisfied condition "Succeeded or Failed" [1mSTEP:[0m resizing the pvc [38;5;243m01/30/23 08:30:15.588[0m [1mSTEP:[0m sleep 30s waiting for resize complete [38;5;243m01/30/23 08:30:15.701[0m [1mSTEP:[0m checking the resizing result [38;5;243m01/30/23 08:30:45.718[0m [1mSTEP:[0m checking the resizing PV result [38;5;243m01/30/23 08:30:45.827[0m [1mSTEP:[0m checking the resizing azurefile result [38;5;243m01/30/23 08:30:45.935[0m Jan 30 08:30:46.979: INFO: deleting Pod "azurefile-4538"/"azurefile-volume-tester-4z4r5" ... skipping 47 lines ... Jan 30 08:29:56.815: INFO: PersistentVolumeClaim pvc-cql2p found but phase is Pending instead of Bound. Jan 30 08:29:58.924: INFO: PersistentVolumeClaim pvc-cql2p found and phase=Bound (31.751004612s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:29:58.924[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:29:59.032[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:29:59.14[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:29:59.14[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:29:59.254[0m Jan 30 08:29:59.254: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4z4r5" in namespace "azurefile-4538" to be "Succeeded or Failed" Jan 30 08:29:59.362: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 107.781466ms Jan 30 08:30:01.471: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.216857858s Jan 30 08:30:03.479: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.224841073s Jan 30 08:30:05.484: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.229718248s Jan 30 08:30:07.478: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=true. Elapsed: 8.224480177s Jan 30 08:30:09.478: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=true. Elapsed: 10.224482687s Jan 30 08:30:11.482: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=true. Elapsed: 12.227752422s Jan 30 08:30:13.481: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Running", Reason="", readiness=false. Elapsed: 14.227193071s Jan 30 08:30:15.479: INFO: Pod "azurefile-volume-tester-4z4r5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.225369348s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:30:15.479[0m Jan 30 08:30:15.479: INFO: Pod "azurefile-volume-tester-4z4r5" satisfied condition "Succeeded or Failed" [1mSTEP:[0m resizing the pvc [38;5;243m01/30/23 08:30:15.588[0m [1mSTEP:[0m sleep 30s waiting for resize complete [38;5;243m01/30/23 08:30:15.701[0m [1mSTEP:[0m checking the resizing result [38;5;243m01/30/23 08:30:45.718[0m [1mSTEP:[0m checking the resizing PV result [38;5;243m01/30/23 08:30:45.827[0m [1mSTEP:[0m checking the resizing azurefile result [38;5;243m01/30/23 08:30:45.935[0m Jan 30 08:30:46.979: INFO: deleting Pod "azurefile-4538"/"azurefile-volume-tester-4z4r5" ... skipping 361 lines ... Jan 30 08:31:20.774: INFO: PersistentVolumeClaim pvc-hlg9k found but phase is Pending instead of Bound. Jan 30 08:31:22.883: INFO: PersistentVolumeClaim pvc-hlg9k found and phase=Bound (2.217161499s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:31:22.883[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:31:22.992[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:31:23.1[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:31:23.101[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:31:23.213[0m Jan 30 08:31:23.213: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-68rdv" in namespace "azurefile-7726" to be "Succeeded or Failed" Jan 30 08:31:23.328: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 115.57569ms Jan 30 08:31:25.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.233419767s Jan 30 08:31:27.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.232865643s Jan 30 08:31:29.447: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.233935977s Jan 30 08:31:31.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.233246656s Jan 30 08:31:33.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.232787825s Jan 30 08:31:35.444: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=true. Elapsed: 12.231025673s Jan 30 08:31:37.445: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=true. Elapsed: 14.231726164s Jan 30 08:31:39.445: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=true. Elapsed: 16.232031895s Jan 30 08:31:41.445: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=false. Elapsed: 18.232018269s Jan 30 08:31:43.444: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.231496266s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:31:43.444[0m Jan 30 08:31:43.445: INFO: Pod "azurefile-volume-tester-68rdv" satisfied condition "Succeeded or Failed" Jan 30 08:31:43.445: INFO: deleting Pod "azurefile-7726"/"azurefile-volume-tester-68rdv" Jan 30 08:31:43.561: INFO: Pod azurefile-volume-tester-68rdv has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-68rdv in namespace azurefile-7726 [38;5;243m01/30/23 08:31:43.561[0m Jan 30 08:31:43.688: INFO: deleting PVC "azurefile-7726"/"pvc-hlg9k" Jan 30 08:31:43.688: INFO: Deleting PersistentVolumeClaim "pvc-hlg9k" ... skipping 122 lines ... Jan 30 08:31:20.774: INFO: PersistentVolumeClaim pvc-hlg9k found but phase is Pending instead of Bound. Jan 30 08:31:22.883: INFO: PersistentVolumeClaim pvc-hlg9k found and phase=Bound (2.217161499s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:31:22.883[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:31:22.992[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:31:23.1[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:31:23.101[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:31:23.213[0m Jan 30 08:31:23.213: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-68rdv" in namespace "azurefile-7726" to be "Succeeded or Failed" Jan 30 08:31:23.328: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 115.57569ms Jan 30 08:31:25.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.233419767s Jan 30 08:31:27.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.232865643s Jan 30 08:31:29.447: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.233935977s Jan 30 08:31:31.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.233246656s Jan 30 08:31:33.446: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.232787825s Jan 30 08:31:35.444: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=true. Elapsed: 12.231025673s Jan 30 08:31:37.445: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=true. Elapsed: 14.231726164s Jan 30 08:31:39.445: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=true. Elapsed: 16.232031895s Jan 30 08:31:41.445: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Running", Reason="", readiness=false. Elapsed: 18.232018269s Jan 30 08:31:43.444: INFO: Pod "azurefile-volume-tester-68rdv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.231496266s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:31:43.444[0m Jan 30 08:31:43.445: INFO: Pod "azurefile-volume-tester-68rdv" satisfied condition "Succeeded or Failed" Jan 30 08:31:43.445: INFO: deleting Pod "azurefile-7726"/"azurefile-volume-tester-68rdv" Jan 30 08:31:43.561: INFO: Pod azurefile-volume-tester-68rdv has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-68rdv in namespace azurefile-7726 [38;5;243m01/30/23 08:31:43.561[0m Jan 30 08:31:43.688: INFO: deleting PVC "azurefile-7726"/"pvc-hlg9k" Jan 30 08:31:43.688: INFO: Deleting PersistentVolumeClaim "pvc-hlg9k" ... skipping 92 lines ... check the driver pods if restarts ... ====================================================================================== 2023/01/30 08:31:50 Check successfully Jan 30 08:31:50.698: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig 2023/01/30 08:31:50 run script: test/utils/get_storage_account_secret_name.sh 2023/01/30 08:31:51 got output: azure-storage-account-f614364cca2934d1f8f84e3-secret , error: <nil> 2023/01/30 08:31:51 got storage account secret name: azure-storage-account-f614364cca2934d1f8f84e3-secret [1mSTEP:[0m setting up the StorageClass [38;5;243m01/30/23 08:31:51.136[0m [1mSTEP:[0m creating a StorageClass [38;5;243m01/30/23 08:31:51.137[0m [1mSTEP:[0m setting up the PVC and PV [38;5;243m01/30/23 08:31:51.25[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:31:51.25[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:31:51.364[0m Jan 30 08:31:51.364: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-knk8f] to have phase Bound Jan 30 08:31:51.471: INFO: PersistentVolumeClaim pvc-knk8f found and phase=Bound (107.155897ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:31:51.471[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:31:51.579[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:31:51.687[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:31:51.687[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:31:51.798[0m Jan 30 08:31:51.798: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dhgzd" in namespace "azurefile-1387" to be "Succeeded or Failed" Jan 30 08:31:51.905: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 107.557196ms Jan 30 08:31:54.015: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.21724241s Jan 30 08:31:56.023: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22487741s Jan 30 08:31:58.022: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.223844185s Jan 30 08:32:00.021: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=true. Elapsed: 8.223556886s Jan 30 08:32:02.021: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=true. Elapsed: 10.223692597s Jan 30 08:32:04.023: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=true. Elapsed: 12.225321842s Jan 30 08:32:06.022: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=false. Elapsed: 14.224328647s Jan 30 08:32:08.023: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.224969058s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:32:08.023[0m Jan 30 08:32:08.023: INFO: Pod "azurefile-volume-tester-dhgzd" satisfied condition "Succeeded or Failed" Jan 30 08:32:08.023: INFO: deleting Pod "azurefile-1387"/"azurefile-volume-tester-dhgzd" Jan 30 08:32:08.140: INFO: Pod azurefile-volume-tester-dhgzd has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-dhgzd in namespace azurefile-1387 [38;5;243m01/30/23 08:32:08.14[0m Jan 30 08:32:08.268: INFO: deleting PVC "azurefile-1387"/"pvc-knk8f" Jan 30 08:32:08.268: INFO: Deleting PersistentVolumeClaim "pvc-knk8f" ... skipping 26 lines ... Jan 30 08:31:51.364: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-knk8f] to have phase Bound Jan 30 08:31:51.471: INFO: PersistentVolumeClaim pvc-knk8f found and phase=Bound (107.155897ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:31:51.471[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:31:51.579[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:31:51.687[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:31:51.687[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:31:51.798[0m Jan 30 08:31:51.798: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dhgzd" in namespace "azurefile-1387" to be "Succeeded or Failed" Jan 30 08:31:51.905: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 107.557196ms Jan 30 08:31:54.015: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.21724241s Jan 30 08:31:56.023: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22487741s Jan 30 08:31:58.022: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.223844185s Jan 30 08:32:00.021: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=true. Elapsed: 8.223556886s Jan 30 08:32:02.021: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=true. Elapsed: 10.223692597s Jan 30 08:32:04.023: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=true. Elapsed: 12.225321842s Jan 30 08:32:06.022: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Running", Reason="", readiness=false. Elapsed: 14.224328647s Jan 30 08:32:08.023: INFO: Pod "azurefile-volume-tester-dhgzd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.224969058s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:32:08.023[0m Jan 30 08:32:08.023: INFO: Pod "azurefile-volume-tester-dhgzd" satisfied condition "Succeeded or Failed" Jan 30 08:32:08.023: INFO: deleting Pod "azurefile-1387"/"azurefile-volume-tester-dhgzd" Jan 30 08:32:08.140: INFO: Pod azurefile-volume-tester-dhgzd has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-dhgzd in namespace azurefile-1387 [38;5;243m01/30/23 08:32:08.14[0m Jan 30 08:32:08.268: INFO: deleting PVC "azurefile-1387"/"pvc-knk8f" Jan 30 08:32:08.268: INFO: Deleting PersistentVolumeClaim "pvc-knk8f" ... skipping 37 lines ... Jan 30 08:32:29.780: INFO: PersistentVolumeClaim pvc-w2pq7 found but phase is Pending instead of Bound. Jan 30 08:32:31.892: INFO: PersistentVolumeClaim pvc-w2pq7 found and phase=Bound (21.204095973s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:32:31.892[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:32:32[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:32:32.108[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:32:32.108[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:32:32.221[0m Jan 30 08:32:32.221: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l4nh9" in namespace "azurefile-4547" to be "Succeeded or Failed" Jan 30 08:32:32.330: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 108.403424ms Jan 30 08:32:34.441: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219225807s Jan 30 08:32:36.439: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21810222s Jan 30 08:32:38.447: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.226130504s Jan 30 08:32:40.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.225061804s Jan 30 08:32:42.447: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=true. Elapsed: 10.226147698s Jan 30 08:32:44.447: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=true. Elapsed: 12.225978262s Jan 30 08:32:46.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=true. Elapsed: 14.22485547s Jan 30 08:32:48.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=false. Elapsed: 16.224252076s Jan 30 08:32:50.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.224668398s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:32:50.446[0m Jan 30 08:32:50.446: INFO: Pod "azurefile-volume-tester-l4nh9" satisfied condition "Succeeded or Failed" Jan 30 08:32:50.446: INFO: deleting Pod "azurefile-4547"/"azurefile-volume-tester-l4nh9" Jan 30 08:32:50.564: INFO: Pod azurefile-volume-tester-l4nh9 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-l4nh9 in namespace azurefile-4547 [38;5;243m01/30/23 08:32:50.564[0m Jan 30 08:32:50.786: INFO: deleting PVC "azurefile-4547"/"pvc-w2pq7" Jan 30 08:32:50.786: INFO: Deleting PersistentVolumeClaim "pvc-w2pq7" ... skipping 36 lines ... Jan 30 08:32:29.780: INFO: PersistentVolumeClaim pvc-w2pq7 found but phase is Pending instead of Bound. Jan 30 08:32:31.892: INFO: PersistentVolumeClaim pvc-w2pq7 found and phase=Bound (21.204095973s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:32:31.892[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:32:32[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:32:32.108[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:32:32.108[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:32:32.221[0m Jan 30 08:32:32.221: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l4nh9" in namespace "azurefile-4547" to be "Succeeded or Failed" Jan 30 08:32:32.330: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 108.403424ms Jan 30 08:32:34.441: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219225807s Jan 30 08:32:36.439: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21810222s Jan 30 08:32:38.447: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.226130504s Jan 30 08:32:40.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.225061804s Jan 30 08:32:42.447: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=true. Elapsed: 10.226147698s Jan 30 08:32:44.447: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=true. Elapsed: 12.225978262s Jan 30 08:32:46.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=true. Elapsed: 14.22485547s Jan 30 08:32:48.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Running", Reason="", readiness=false. Elapsed: 16.224252076s Jan 30 08:32:50.446: INFO: Pod "azurefile-volume-tester-l4nh9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.224668398s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:32:50.446[0m Jan 30 08:32:50.446: INFO: Pod "azurefile-volume-tester-l4nh9" satisfied condition "Succeeded or Failed" Jan 30 08:32:50.446: INFO: deleting Pod "azurefile-4547"/"azurefile-volume-tester-l4nh9" Jan 30 08:32:50.564: INFO: Pod azurefile-volume-tester-l4nh9 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-l4nh9 in namespace azurefile-4547 [38;5;243m01/30/23 08:32:50.564[0m Jan 30 08:32:50.786: INFO: deleting PVC "azurefile-4547"/"pvc-w2pq7" Jan 30 08:32:50.786: INFO: Deleting PersistentVolumeClaim "pvc-w2pq7" ... skipping 37 lines ... Jan 30 08:33:12.295: INFO: PersistentVolumeClaim pvc-2ckr6 found but phase is Pending instead of Bound. Jan 30 08:33:14.406: INFO: PersistentVolumeClaim pvc-2ckr6 found and phase=Bound (21.199997067s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:33:14.406[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:33:14.514[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:33:14.622[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:33:14.622[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:33:14.733[0m Jan 30 08:33:14.734: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-pdq7k" in namespace "azurefile-7051" to be "Succeeded or Failed" Jan 30 08:33:14.841: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 107.439977ms Jan 30 08:33:16.950: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.216045115s Jan 30 08:33:18.957: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223648306s Jan 30 08:33:20.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224561801s Jan 30 08:33:22.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=true. Elapsed: 8.224350856s Jan 30 08:33:24.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=true. Elapsed: 10.224811621s Jan 30 08:33:26.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=true. Elapsed: 12.22434533s Jan 30 08:33:28.957: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=false. Elapsed: 14.223067923s Jan 30 08:33:30.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.224338776s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:33:30.958[0m Jan 30 08:33:30.958: INFO: Pod "azurefile-volume-tester-pdq7k" satisfied condition "Succeeded or Failed" Jan 30 08:33:30.958: INFO: deleting Pod "azurefile-7051"/"azurefile-volume-tester-pdq7k" Jan 30 08:33:31.075: INFO: Pod azurefile-volume-tester-pdq7k has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-pdq7k in namespace azurefile-7051 [38;5;243m01/30/23 08:33:31.075[0m Jan 30 08:33:31.297: INFO: deleting PVC "azurefile-7051"/"pvc-2ckr6" Jan 30 08:33:31.297: INFO: Deleting PersistentVolumeClaim "pvc-2ckr6" ... skipping 36 lines ... Jan 30 08:33:12.295: INFO: PersistentVolumeClaim pvc-2ckr6 found but phase is Pending instead of Bound. Jan 30 08:33:14.406: INFO: PersistentVolumeClaim pvc-2ckr6 found and phase=Bound (21.199997067s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:33:14.406[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:33:14.514[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:33:14.622[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:33:14.622[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:33:14.733[0m Jan 30 08:33:14.734: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-pdq7k" in namespace "azurefile-7051" to be "Succeeded or Failed" Jan 30 08:33:14.841: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 107.439977ms Jan 30 08:33:16.950: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.216045115s Jan 30 08:33:18.957: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223648306s Jan 30 08:33:20.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224561801s Jan 30 08:33:22.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=true. Elapsed: 8.224350856s Jan 30 08:33:24.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=true. Elapsed: 10.224811621s Jan 30 08:33:26.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=true. Elapsed: 12.22434533s Jan 30 08:33:28.957: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Running", Reason="", readiness=false. Elapsed: 14.223067923s Jan 30 08:33:30.958: INFO: Pod "azurefile-volume-tester-pdq7k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.224338776s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:33:30.958[0m Jan 30 08:33:30.958: INFO: Pod "azurefile-volume-tester-pdq7k" satisfied condition "Succeeded or Failed" Jan 30 08:33:30.958: INFO: deleting Pod "azurefile-7051"/"azurefile-volume-tester-pdq7k" Jan 30 08:33:31.075: INFO: Pod azurefile-volume-tester-pdq7k has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-pdq7k in namespace azurefile-7051 [38;5;243m01/30/23 08:33:31.075[0m Jan 30 08:33:31.297: INFO: deleting PVC "azurefile-7051"/"pvc-2ckr6" Jan 30 08:33:31.297: INFO: Deleting PersistentVolumeClaim "pvc-2ckr6" ... skipping 31 lines ... I0130 08:33:41.827206 41777 testsuites.go:627] 0/1 replicas in the StatefulSet are ready I0130 08:33:43.825797 41777 testsuites.go:627] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/30/23 08:33:43.941[0m [1mSTEP:[0m check pod exec [38;5;243m01/30/23 08:33:44.057[0m Jan 30 08:33:44.057: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:33:45.275: INFO: rc: 1 Jan 30 08:33:45.275: INFO: Error waiting for output "hello world\r\n" in pod "azurefile-volume-tester-n8m2l-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 30 08:33:47.276: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:33:48.470: INFO: stderr: "" Jan 30 08:33:48.470: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/30/23 08:33:48.47[0m Jan 30 08:33:48.471: INFO: Deleting pod "azurefile-volume-tester-n8m2l-0" in namespace "azurefile-9183" ... skipping 124 lines ... Jan 30 08:35:51.045: INFO: stdout: "hello world\r\n" Jan 30 08:35:51.045: INFO: The stdout did not contain output "hello world\r\nhello world\r\n" in pod "azurefile-volume-tester-n8m2l-0", found: "hello world\r\n". Jan 30 08:35:51.045: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:35:52.185: INFO: stderr: "" Jan 30 08:35:52.185: INFO: stdout: "hello world\r\n" Jan 30 08:35:52.185: INFO: The stdout did not contain output "hello world\r\nhello world\r\n" in pod "azurefile-volume-tester-n8m2l-0", found: "hello world\r\n". Jan 30 08:35:52.185: INFO: Unexpected error: Failed to find "hello world\r\nhello world\r\n" in at least one pod's output.: <errors.aggregate | len:1, cap:1>: [ <*errors.errorString | 0xc000375730>{ s: "timed out waiting for the condition", }, ] Jan 30 08:35:52.185: FAIL: Failed to find "hello world\r\nhello world\r\n" in at least one pod's output.: timed out waiting for the condition Full Stack Trace sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites.pollForStringInPodsExec({0xc000bb3780, 0xe}, {0xc000a6dde0, 0x1, 0x7f569c42aa00?}, {0xc000893590, 0x3, 0x3}, {0xc000a48480, 0x1a}) /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:1011 +0x25e sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites.(*TestStatefulset).PollForStringInPodsExec(...) /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:589 ... skipping 4 lines ... Jan 30 08:35:52.185: INFO: deleting StatefulSet "azurefile-9183"/"azurefile-volume-tester-n8m2l" Jan 30 08:35:52.312: INFO: Pod azurefile-volume-tester-n8m2l-0 has the following logs: Jan 30 08:35:52.423: INFO: deleting StorageClass azurefile-9183-file.csi.azure.com-dynamic-sc-dwpv5 [1mSTEP:[0m dump namespace information after failure [38;5;243m01/30/23 08:35:52.534[0m [1mSTEP:[0m Destroying namespace "azurefile-9183" for this suite. [38;5;243m01/30/23 08:35:52.534[0m [38;5;243m------------------------------[0m [38;5;9m• [FAILED] [140.688 seconds][0m Dynamic Provisioning [38;5;243m/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:43[0m [38;5;9m[1m[It] should create a statefulset object, write and read to it, delete the pod and write and read to it again [file.csi.azure.com][0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:832[0m [38;5;243mBegin Captured GinkgoWriter Output >>[0m ... skipping 15 lines ... I0130 08:33:41.827206 41777 testsuites.go:627] 0/1 replicas in the StatefulSet are ready I0130 08:33:43.825797 41777 testsuites.go:627] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/30/23 08:33:43.941[0m [1mSTEP:[0m check pod exec [38;5;243m01/30/23 08:33:44.057[0m Jan 30 08:33:44.057: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:33:45.275: INFO: rc: 1 Jan 30 08:33:45.275: INFO: Error waiting for output "hello world\r\n" in pod "azurefile-volume-tester-n8m2l-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 30 08:33:47.276: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:33:48.470: INFO: stderr: "" Jan 30 08:33:48.470: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/30/23 08:33:48.47[0m Jan 30 08:33:48.471: INFO: Deleting pod "azurefile-volume-tester-n8m2l-0" in namespace "azurefile-9183" ... skipping 124 lines ... Jan 30 08:35:51.045: INFO: stdout: "hello world\r\n" Jan 30 08:35:51.045: INFO: The stdout did not contain output "hello world\r\nhello world\r\n" in pod "azurefile-volume-tester-n8m2l-0", found: "hello world\r\n". Jan 30 08:35:51.045: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-9183 exec azurefile-volume-tester-n8m2l-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:35:52.185: INFO: stderr: "" Jan 30 08:35:52.185: INFO: stdout: "hello world\r\n" Jan 30 08:35:52.185: INFO: The stdout did not contain output "hello world\r\nhello world\r\n" in pod "azurefile-volume-tester-n8m2l-0", found: "hello world\r\n". Jan 30 08:35:52.185: INFO: Unexpected error: Failed to find "hello world\r\nhello world\r\n" in at least one pod's output.: <errors.aggregate | len:1, cap:1>: [ <*errors.errorString | 0xc000375730>{ s: "timed out waiting for the condition", }, ] Jan 30 08:35:52.185: FAIL: Failed to find "hello world\r\nhello world\r\n" in at least one pod's output.: timed out waiting for the condition Full Stack Trace sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites.pollForStringInPodsExec({0xc000bb3780, 0xe}, {0xc000a6dde0, 0x1, 0x7f569c42aa00?}, {0xc000893590, 0x3, 0x3}, {0xc000a48480, 0x1a}) /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:1011 +0x25e sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites.(*TestStatefulset).PollForStringInPodsExec(...) /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:589 ... skipping 5 lines ... Jan 30 08:35:52.312: INFO: Pod azurefile-volume-tester-n8m2l-0 has the following logs: Jan 30 08:35:52.423: INFO: deleting StorageClass azurefile-9183-file.csi.azure.com-dynamic-sc-dwpv5 [1mSTEP:[0m dump namespace information after failure [38;5;243m01/30/23 08:35:52.534[0m [1mSTEP:[0m Destroying namespace "azurefile-9183" for this suite. [38;5;243m01/30/23 08:35:52.534[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;9mJan 30 08:35:52.185: Failed to find "hello world\r\nhello world\r\n" in at least one pod's output.: timed out waiting for the condition[0m [38;5;9mIn [1m[It][0m[38;5;9m at: [1m/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:1011[0m [1mThere were additional failures detected after the initial failure:[0m [38;5;13m[PANICKED][0m [38;5;13mTest Panicked[0m [38;5;13mIn [1m[DeferCleanup (Each)][0m[38;5;13m at: [1m/usr/local/go/src/runtime/panic.go:260[0m [38;5;13mruntime error: invalid memory address or nil pointer dereference[0m [38;5;13mFull Stack Trace[0m k8s.io/kubernetes/test/e2e/framework.(*Framework).dumpNamespaceInfo.func1() /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:274 +0x5c k8s.io/kubernetes/test/e2e/framework.(*Framework).dumpNamespaceInfo(0xc00010e1e0) /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:271 +0x179 ... skipping 33 lines ... Jan 30 08:36:01.033: 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(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-nqghh-7fc89bf56b\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 30 08:36:03.030: 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(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-nqghh-7fc89bf56b\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/30/23 08:36:05.256[0m [1mSTEP:[0m check pod exec [38;5;243m01/30/23 08:36:06.48[0m Jan 30 08:36:06.481: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-8154 exec azurefile-volume-tester-nqghh-7fc89bf56b-25bdr -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:36:07.663: INFO: rc: 1 Jan 30 08:36:07.663: INFO: Error waiting for output "hello world\r\n" in pod "azurefile-volume-tester-nqghh-7fc89bf56b-25bdr": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-8154 exec azurefile-volume-tester-nqghh-7fc89bf56b-25bdr -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 30 08:36:09.663: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-8154 exec azurefile-volume-tester-nqghh-7fc89bf56b-25bdr -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:36:10.854: INFO: stderr: "" Jan 30 08:36:10.854: INFO: stdout: "hello world\r\n" [1mSTEP:[0m delete volume capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154 first, make sure pod could still be terminated [38;5;243m01/30/23 08:36:10.854[0m [1mSTEP:[0m check whether capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154 exists [38;5;243m01/30/23 08:36:11.943[0m [1mSTEP:[0m ValidateVolumeCapabilities capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154 returned with error: rpc error: code = NotFound desc = the requested volume(capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154) does not exist. [38;5;243m01/30/23 08:36:12.704[0m [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/30/23 08:36:12.704[0m Jan 30 08:36:12.704: INFO: Deleting pod "azurefile-volume-tester-nqghh-7fc89bf56b-25bdr" in namespace "azurefile-8154" Jan 30 08:36:12.825: INFO: Waiting for pod "azurefile-volume-tester-nqghh-7fc89bf56b-25bdr" in namespace "azurefile-8154" to be fully deleted Jan 30 08:36:15.049: INFO: deleting Deployment "azurefile-8154"/"azurefile-volume-tester-nqghh" Jan 30 08:36:15.156: INFO: Error getting logs for pod azurefile-volume-tester-nqghh-7fc89bf56b-25bdr: the server could not find the requested resource (get pods azurefile-volume-tester-nqghh-7fc89bf56b-25bdr) Jan 30 08:36:15.267: INFO: deleting PVC "azurefile-8154"/"pvc-v6mbs" Jan 30 08:36:15.267: INFO: Deleting PersistentVolumeClaim "pvc-v6mbs" [1mSTEP:[0m waiting for claim's PV "pvc-15853679-f2d3-4592-8e22-10bb31b16335" to be deleted [38;5;243m01/30/23 08:36:15.601[0m Jan 30 08:36:15.601: INFO: Waiting up to 10m0s for PersistentVolume pvc-15853679-f2d3-4592-8e22-10bb31b16335 to get deleted Jan 30 08:36:15.708: INFO: PersistentVolume pvc-15853679-f2d3-4592-8e22-10bb31b16335 found and phase=Bound (107.244136ms) Jan 30 08:36:20.817: INFO: PersistentVolume pvc-15853679-f2d3-4592-8e22-10bb31b16335 found and phase=Bound (5.216317624s) ... skipping 34 lines ... Jan 30 08:36:01.033: 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(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-nqghh-7fc89bf56b\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 30 08:36:03.030: 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(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 30, 8, 35, 56, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azurefile-volume-tester-nqghh-7fc89bf56b\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/30/23 08:36:05.256[0m [1mSTEP:[0m check pod exec [38;5;243m01/30/23 08:36:06.48[0m Jan 30 08:36:06.481: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-8154 exec azurefile-volume-tester-nqghh-7fc89bf56b-25bdr -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:36:07.663: INFO: rc: 1 Jan 30 08:36:07.663: INFO: Error waiting for output "hello world\r\n" in pod "azurefile-volume-tester-nqghh-7fc89bf56b-25bdr": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-8154 exec azurefile-volume-tester-nqghh-7fc89bf56b-25bdr -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 30 08:36:09.663: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azurefile-8154 exec azurefile-volume-tester-nqghh-7fc89bf56b-25bdr -- cmd /c type C:\mnt\test-1\data.txt' Jan 30 08:36:10.854: INFO: stderr: "" Jan 30 08:36:10.854: INFO: stdout: "hello world\r\n" [1mSTEP:[0m delete volume capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154 first, make sure pod could still be terminated [38;5;243m01/30/23 08:36:10.854[0m [1mSTEP:[0m check whether capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154 exists [38;5;243m01/30/23 08:36:11.943[0m [1mSTEP:[0m ValidateVolumeCapabilities capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154 returned with error: rpc error: code = NotFound desc = the requested volume(capz-e7g6lu#f1702085db7074cc1afb52f#pvc-15853679-f2d3-4592-8e22-10bb31b16335###azurefile-8154) does not exist. [38;5;243m01/30/23 08:36:12.704[0m [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/30/23 08:36:12.704[0m Jan 30 08:36:12.704: INFO: Deleting pod "azurefile-volume-tester-nqghh-7fc89bf56b-25bdr" in namespace "azurefile-8154" Jan 30 08:36:12.825: INFO: Waiting for pod "azurefile-volume-tester-nqghh-7fc89bf56b-25bdr" in namespace "azurefile-8154" to be fully deleted Jan 30 08:36:15.049: INFO: deleting Deployment "azurefile-8154"/"azurefile-volume-tester-nqghh" Jan 30 08:36:15.156: INFO: Error getting logs for pod azurefile-volume-tester-nqghh-7fc89bf56b-25bdr: the server could not find the requested resource (get pods azurefile-volume-tester-nqghh-7fc89bf56b-25bdr) Jan 30 08:36:15.267: INFO: deleting PVC "azurefile-8154"/"pvc-v6mbs" Jan 30 08:36:15.267: INFO: Deleting PersistentVolumeClaim "pvc-v6mbs" [1mSTEP:[0m waiting for claim's PV "pvc-15853679-f2d3-4592-8e22-10bb31b16335" to be deleted [38;5;243m01/30/23 08:36:15.601[0m Jan 30 08:36:15.601: INFO: Waiting up to 10m0s for PersistentVolume pvc-15853679-f2d3-4592-8e22-10bb31b16335 to get deleted Jan 30 08:36:15.708: INFO: PersistentVolume pvc-15853679-f2d3-4592-8e22-10bb31b16335 found and phase=Bound (107.244136ms) Jan 30 08:36:20.817: INFO: PersistentVolume pvc-15853679-f2d3-4592-8e22-10bb31b16335 found and phase=Bound (5.216317624s) ... skipping 50 lines ... check the driver pods if restarts ... ====================================================================================== 2023/01/30 08:36:29 Check successfully Jan 30 08:36:29.218: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig 2023/01/30 08:36:29 run script: test/utils/get_storage_account_secret_name.sh 2023/01/30 08:36:29 got output: azure-storage-account-f614364cca2934d1f8f84e3-secret , error: <nil> 2023/01/30 08:36:29 got storage account secret name: azure-storage-account-f614364cca2934d1f8f84e3-secret [1mSTEP:[0m Successfully provisioned AzureFile volume: "capz-e7g6lu#f614364cca2934d1f8f84e3#csi-inline-smb-volume##csi-inline-smb-volume#azurefile-9371" [38;5;243m01/30/23 08:36:31.652[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:36:31.652[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:36:31.764[0m Jan 30 08:36:31.764: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-rhkml" in namespace "azurefile-9371" to be "Succeeded or Failed" Jan 30 08:36:31.872: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 107.875344ms Jan 30 08:36:33.981: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217204571s Jan 30 08:36:35.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 4.224344577s Jan 30 08:36:37.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 6.223679903s Jan 30 08:36:39.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=true. Elapsed: 8.223808521s Jan 30 08:36:41.989: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=true. Elapsed: 10.225303383s Jan 30 08:36:43.989: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=true. Elapsed: 12.224437321s Jan 30 08:36:45.987: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=false. Elapsed: 14.223354868s Jan 30 08:36:47.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.223702113s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:36:47.988[0m Jan 30 08:36:47.988: INFO: Pod "azurefile-volume-tester-rhkml" satisfied condition "Succeeded or Failed" Jan 30 08:36:47.988: INFO: deleting Pod "azurefile-9371"/"azurefile-volume-tester-rhkml" Jan 30 08:36:48.107: INFO: Pod azurefile-volume-tester-rhkml has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-rhkml in namespace azurefile-9371 [38;5;243m01/30/23 08:36:48.107[0m [1mSTEP:[0m Destroying namespace "azurefile-9371" for this suite. [38;5;243m01/30/23 08:36:48.232[0m [38;5;243m------------------------------[0m ... skipping 10 lines ... [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m01/30/23 08:36:28.121[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m01/30/23 08:36:28.336[0m Jan 30 08:36:29.218: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig [1mSTEP:[0m Successfully provisioned AzureFile volume: "capz-e7g6lu#f614364cca2934d1f8f84e3#csi-inline-smb-volume##csi-inline-smb-volume#azurefile-9371" [38;5;243m01/30/23 08:36:31.652[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:36:31.652[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:36:31.764[0m Jan 30 08:36:31.764: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-rhkml" in namespace "azurefile-9371" to be "Succeeded or Failed" Jan 30 08:36:31.872: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 107.875344ms Jan 30 08:36:33.981: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217204571s Jan 30 08:36:35.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 4.224344577s Jan 30 08:36:37.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Pending", Reason="", readiness=false. Elapsed: 6.223679903s Jan 30 08:36:39.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=true. Elapsed: 8.223808521s Jan 30 08:36:41.989: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=true. Elapsed: 10.225303383s Jan 30 08:36:43.989: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=true. Elapsed: 12.224437321s Jan 30 08:36:45.987: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Running", Reason="", readiness=false. Elapsed: 14.223354868s Jan 30 08:36:47.988: INFO: Pod "azurefile-volume-tester-rhkml": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.223702113s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:36:47.988[0m Jan 30 08:36:47.988: INFO: Pod "azurefile-volume-tester-rhkml" satisfied condition "Succeeded or Failed" Jan 30 08:36:47.988: INFO: deleting Pod "azurefile-9371"/"azurefile-volume-tester-rhkml" Jan 30 08:36:48.107: INFO: Pod azurefile-volume-tester-rhkml has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-rhkml in namespace azurefile-9371 [38;5;243m01/30/23 08:36:48.107[0m [1mSTEP:[0m Destroying namespace "azurefile-9371" for this suite. [38;5;243m01/30/23 08:36:48.232[0m [38;5;243m<< End Captured GinkgoWriter Output[0m ... skipping 231 lines ... Streaming logs below: I0130 08:19:35.907852 1 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test I0130 08:19:35.907956 1 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0130 08:19:35.908278 1 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I0130 08:19:35.964924 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 56 milliseconds I0130 08:19:35.965216 1 azure.go:87] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0130 08:19:35.965226 1 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:19:35.965232 1 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0130 08:19:35.965280 1 azure.go:110] read cloud config from file: /etc/kubernetes/azure.json successfully I0130 08:19:35.966213 1 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:19:35.966253 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:19:35.966321 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0130 08:19:35.966374 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0130 08:19:35.966456 1 azure.go:1010] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0130 08:19:35.966470 1 azure.go:140] disable UseInstanceMetadata for controller server I0130 08:19:35.966475 1 azure.go:143] starting controller server... I0130 08:19:35.966490 1 azurefile.go:304] cloud: AzurePublicCloud, location: westeurope, rg: capz-e7g6lu, VnetName: capz-e7g6lu-vnet, VnetResourceGroup: capz-e7g6lu, SubnetName: node-subnet I0130 08:19:35.970139 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount1860059089' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount1860059089: must be superuser to unmount. I0130 08:19:35.970162 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0130 08:19:35.970219 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME I0130 08:19:35.970225 1 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0130 08:19:35.970229 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0130 08:19:35.970233 1 driver.go:93] Enabling controller service capability: EXPAND_VOLUME I0130 08:19:35.970236 1 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER ... skipping 447 lines ... Pragma: no-cache Content-Type: application/json; charset=utf-8 X-Ms-Request-Id: 7658578c-01ba-4474-8fb6-1a1d50fbd5cb X-Ms-Routing-Request-Id: WESTEUROPE:20230130T082036Z:7658578c-01ba-4474-8fb6-1a1d50fbd5cb Strict-Transport-Security: max-age=31536000; includeSubDomains I0130 08:20:36.587907 1 util.go:124] Send.sendRequest got response with ContentLength 250, StatusCode 404 and responseBody length 250 I0130 08:20:36.587976 1 azure_privatednsclient.go:215] Received error in privatednszone.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net, error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:20:36.588146 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.019923872 request="private_dns_zones_get" resource_group="capz-e7g6lu" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I0130 08:20:36.588166 1 azure_storageaccount.go:239] get private dns zone privatelink.file.core.windows.net returned with Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:20:36.588186 1 azure_storageaccount.go:464] Creating private dns zone(privatelink.file.core.windows.net) in resourceGroup (capz-e7g6lu) (2023-01-30T08:20:36.5883000Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 User-Agent: Go/go1.19.5 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test Authorization: **REDACTED** Content-Type: application/json; charset=utf-8 (2023-01-30T08:20:36.5883519Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 ... skipping 140 lines ... X-Ms-Failure-Cause: gateway X-Content-Type-Options: nosniff Date: Mon, 30 Jan 2023 08:21:07 GMT Content-Length: 296 Cache-Control: no-cache I0130 08:21:08.299935 1 util.go:124] Send.sendRequest got response with ContentLength 296, StatusCode 404 and responseBody length 296 I0130 08:21:08.299950 1 azure_virtualnetworklinksclient.go:212] Received error in virtualnetworklink.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink, error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:21:08.300036 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.054038339 request="virtual_network_links_get" resource_group="capz-e7g6lu" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I0130 08:21:08.300054 1 azure_storageaccount.go:249] get virtual link for vnet(capz-e7g6lu-vnet) and DNS Zone(privatelink.file.core.windows.net) returned with Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:21:08.300060 1 azure_storageaccount.go:478] Creating virtual link for vnet(capz-e7g6lu-vnet-vnetlink) and DNS Zone(privatelink.file.core.windows.net) in resourceGroup(capz-e7g6lu) (2023-01-30T08:21:08.3001522Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink?api-version=2020-06-01 User-Agent: Go/go1.19.5 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test Authorization: **REDACTED** Content-Type: application/json; charset=utf-8 (2023-01-30T08:21:08.3001892Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink?api-version=2020-06-01 ... skipping 4538 lines ... Streaming logs below: I0130 08:20:02.652830 6916 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test I0130 08:20:02.662335 6916 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0130 08:20:02.667332 6916 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I0130 08:20:02.684831 6916 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 15 milliseconds I0130 08:20:02.686327 6916 azure.go:87] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0130 08:20:02.686327 6916 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:20:02.686327 6916 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0130 08:20:02.686327 6916 azure.go:110] read cloud config from file: C:\k\azure.json successfully I0130 08:20:02.688339 6916 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:20:02.688825 6916 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:20:02.689834 6916 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 1255 lines ... I0130 08:33:52.678262 6916 utils.go:77] GRPC request: {} I0130 08:33:52.678262 6916 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]} I0130 08:33:52.679265 6916 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume I0130 08:33:52.679265 6916 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\\globalmount","target_path":"c:\\var\\lib\\kubelet\\pods\\61cdbb43-0725-4152-a9c8-7a67afd78fd2\\volumes\\kubernetes.io~csi\\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\\mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"azurefile-volume-tester-n8m2l-0","csi.storage.k8s.io/pod.namespace":"azurefile-9183","csi.storage.k8s.io/pod.uid":"61cdbb43-0725-4152-a9c8-7a67afd78fd2","csi.storage.k8s.io/pv/name":"pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10","csi.storage.k8s.io/pvc/name":"pvc-azurefile-volume-tester-n8m2l-0","csi.storage.k8s.io/pvc/namespace":"azurefile-9183","csi.storage.k8s.io/serviceAccount.name":"default","secretnamespace":"azurefile-9183","skuName":"Standard_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1675066776049-8081-file.csi.azure.com"},"volume_id":"capz-e7g6lu#f614364cca2934d1f8f84e3#pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10###azurefile-9183"} I0130 08:33:52.679265 6916 safe_mounter_windows.go:155] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount I0130 08:33:52.679265 6916 safe_mounter_windows.go:212] Exists path: c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount W0130 08:33:52.719633 6916 nodeserver.go:529] ReadDir c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount failed with open c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount: Access is denied., unmount this directory I0130 08:33:52.720635 6916 safe_mounter_windows.go:139] Unmount: c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount I0130 08:33:52.720635 6916 safe_mounter_windows.go:125] Remove directory: c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount E0130 08:33:52.721640 6916 utils.go:81] GRPC error: rpc error: code = Internal desc = Could not mount target c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount: open c:\var\lib\kubelet\pods\61cdbb43-0725-4152-a9c8-7a67afd78fd2\volumes\kubernetes.io~csi\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\mount: Access is denied. I0130 08:34:04.590182 6916 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities I0130 08:34:04.590182 6916 utils.go:77] GRPC request: {} I0130 08:34:04.590182 6916 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]} I0130 08:34:04.591183 6916 utils.go:76] GRPC call: /csi.v1.Node/NodeGetVolumeStats I0130 08:34:04.591183 6916 utils.go:77] GRPC request: {"volume_id":"capz-e7g6lu#f614364cca2934d1f8f84e3#pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10###azurefile-9183","volume_path":"c:\\var\\lib\\kubelet\\pods\\61cdbb43-0725-4152-a9c8-7a67afd78fd2\\volumes\\kubernetes.io~csi\\pvc-7ae1f71e-cff5-4e0d-a92b-5670aa3c6a10\\mount"} I0130 08:34:04.591698 6916 utils.go:83] GRPC response: {"usage":[{"available":120752549888,"total":136912564224,"unit":1,"used":16160014336},{"unit":2}]} ... skipping 117 lines ... I0130 08:36:31.857655 6916 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities I0130 08:36:31.857655 6916 utils.go:77] GRPC request: {} I0130 08:36:31.857655 6916 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]} I0130 08:36:31.858667 6916 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume I0130 08:36:31.859163 6916 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\48f10738-08cd-431f-b3b8-b76694def1cb\\volumes\\kubernetes.io~csi\\test-volume-1\\mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/ephemeral":"true","csi.storage.k8s.io/pod.name":"azurefile-volume-tester-rhkml","csi.storage.k8s.io/pod.namespace":"azurefile-9371","csi.storage.k8s.io/pod.uid":"48f10738-08cd-431f-b3b8-b76694def1cb","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"dir_mode=0755,file_mode=0721,cache=singleclient","secretName":"azure-storage-account-f614364cca2934d1f8f84e3-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-462904507f5e8d794899b5c83665caaf2c5fe5bec11af91d8bbbd6f072bbf855"} I0130 08:36:31.859163 6916 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-462904507f5e8d794899b5c83665caaf2c5fe5bec11af91d8bbbd6f072bbf855) mount on c:\var\lib\kubelet\pods\48f10738-08cd-431f-b3b8-b76694def1cb\volumes\kubernetes.io~csi\test-volume-1\mount, VolumeContext: map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-rhkml csi.storage.k8s.io/pod.namespace:azurefile-9371 csi.storage.k8s.io/pod.uid:48f10738-08cd-431f-b3b8-b76694def1cb csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:dir_mode=0755,file_mode=0721,cache=singleclient secretName:azure-storage-account-f614364cca2934d1f8f84e3-secret secretnamespace:azurefile-9371 server: shareName:csi-inline-smb-volume storageaccount:] W0130 08:36:31.859163 6916 azurefile.go:595] parsing volumeID(csi-462904507f5e8d794899b5c83665caaf2c5fe5bec11af91d8bbbd6f072bbf855) return with error: error parsing volume id: "csi-462904507f5e8d794899b5c83665caaf2c5fe5bec11af91d8bbbd6f072bbf855", should at least contain two # I0130 08:36:31.861657 6916 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/azurefile-9371/secrets/azure-storage-account-f614364cca2934d1f8f84e3-secret 200 OK in 2 milliseconds I0130 08:36:31.862165 6916 nodeserver.go:302] cifsMountPath(c:\var\lib\kubelet\pods\48f10738-08cd-431f-b3b8-b76694def1cb\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-462904507f5e8d794899b5c83665caaf2c5fe5bec11af91d8bbbd6f072bbf855) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-rhkml csi.storage.k8s.io/pod.namespace:azurefile-9371 csi.storage.k8s.io/pod.uid:48f10738-08cd-431f-b3b8-b76694def1cb csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:dir_mode=0755,file_mode=0721,cache=singleclient secretName:azure-storage-account-f614364cca2934d1f8f84e3-secret secretnamespace:azurefile-9371 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\f614364cca2934d1f8f84e3]) volumeMountGroup() I0130 08:36:31.862165 6916 safe_mounter_windows.go:155] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\48f10738-08cd-431f-b3b8-b76694def1cb\volumes\kubernetes.io~csi\test-volume-1\mount I0130 08:36:31.862165 6916 safe_mounter_windows.go:212] Exists path: c:\var\lib\kubelet\pods\48f10738-08cd-431f-b3b8-b76694def1cb\volumes\kubernetes.io~csi\test-volume-1\mount I0130 08:36:31.863163 6916 safe_mounter_windows.go:212] Exists path: c:\var\lib\kubelet\pods\48f10738-08cd-431f-b3b8-b76694def1cb\volumes\kubernetes.io~csi\test-volume-1\mount I0130 08:36:31.863668 6916 azure_common_windows.go:52] Removing path: c:\var\lib\kubelet\pods\48f10738-08cd-431f-b3b8-b76694def1cb\volumes\kubernetes.io~csi\test-volume-1\mount ... skipping 34 lines ... Streaming logs below: I0130 08:20:02.443482 3396 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test I0130 08:20:02.444663 3396 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0130 08:20:02.451816 3396 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I0130 08:20:02.472609 3396 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 14 milliseconds I0130 08:20:02.474060 3396 azure.go:87] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0130 08:20:02.474060 3396 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:20:02.474060 3396 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0130 08:20:02.474238 3396 azure.go:110] read cloud config from file: C:\k\azure.json successfully I0130 08:20:02.475454 3396 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:20:02.476530 3396 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:20:02.478714 3396 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 547 lines ... # HELP go_gc_heap_objects_objects Number of objects, live or unswept, occupying heap memory. # TYPE go_gc_heap_objects_objects gauge go_gc_heap_objects_objects 53862 # HELP go_gc_heap_tiny_allocs_objects_total Count of small allocations that are packed together into blocks. These allocations are counted separately from other allocations because each individual allocation is not tracked by the runtime, only their block. Each block is already accounted for in allocs-by-size and frees-by-size. # TYPE go_gc_heap_tiny_allocs_objects_total counter go_gc_heap_tiny_allocs_objects_total 17549 # HELP go_gc_limiter_last_enabled_gc_cycle GC cycle the last time the GC CPU limiter was enabled. This metric is useful for diagnosing the root cause of an out-of-memory error, because the limiter trades memory for CPU time when the GC's CPU time gets too high. This is most likely to occur with use of SetMemoryLimit. The first GC cycle is cycle 1, so a value of 0 indicates that it was never enabled. # TYPE go_gc_limiter_last_enabled_gc_cycle gauge go_gc_limiter_last_enabled_gc_cycle 0 # HELP go_gc_pauses_seconds Distribution individual GC-related stop-the-world pause latencies. # TYPE go_gc_pauses_seconds histogram go_gc_pauses_seconds_bucket{le="9.999999999999999e-10"} 0 go_gc_pauses_seconds_bucket{le="9.999999999999999e-09"} 0 ... skipping 341 lines ... Jan 30 08:38:05.325: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lfzcd] to have phase Bound Jan 30 08:38:05.433: INFO: PersistentVolumeClaim pvc-lfzcd found and phase=Bound (107.823712ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:05.433[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:05.541[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:05.649[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:05.649[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m01/30/23 08:38:05.761[0m Jan 30 08:38:05.761: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dt8kq" in namespace "azurefile-60" to be "Error status code" Jan 30 08:38:05.869: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 107.799343ms Jan 30 08:38:07.978: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217355507s Jan 30 08:38:09.984: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223424105s Jan 30 08:38:11.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224021836s Jan 30 08:38:13.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=true. Elapsed: 8.224130942s Jan 30 08:38:15.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=true. Elapsed: 10.224496739s Jan 30 08:38:17.986: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=true. Elapsed: 12.224577661s Jan 30 08:38:19.986: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=false. Elapsed: 14.225175471s Jan 30 08:38:21.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Failed", Reason="", readiness=false. Elapsed: 16.224470752s [1mSTEP:[0m Saw pod failure [38;5;243m01/30/23 08:38:21.985[0m Jan 30 08:38:21.986: INFO: Pod "azurefile-volume-tester-dt8kq" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/30/23 08:38:21.986[0m Jan 30 08:38:22.105: INFO: deleting Pod "azurefile-60"/"azurefile-volume-tester-dt8kq" Jan 30 08:38:22.217: INFO: Pod azurefile-volume-tester-dt8kq has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied. At line:1 char:22 + ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 48 lines ... Jan 30 08:38:05.325: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lfzcd] to have phase Bound Jan 30 08:38:05.433: INFO: PersistentVolumeClaim pvc-lfzcd found and phase=Bound (107.823712ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:05.433[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:05.541[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:05.649[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:05.649[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m01/30/23 08:38:05.761[0m Jan 30 08:38:05.761: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-dt8kq" in namespace "azurefile-60" to be "Error status code" Jan 30 08:38:05.869: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 107.799343ms Jan 30 08:38:07.978: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217355507s Jan 30 08:38:09.984: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223424105s Jan 30 08:38:11.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224021836s Jan 30 08:38:13.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=true. Elapsed: 8.224130942s Jan 30 08:38:15.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=true. Elapsed: 10.224496739s Jan 30 08:38:17.986: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=true. Elapsed: 12.224577661s Jan 30 08:38:19.986: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Running", Reason="", readiness=false. Elapsed: 14.225175471s Jan 30 08:38:21.985: INFO: Pod "azurefile-volume-tester-dt8kq": Phase="Failed", Reason="", readiness=false. Elapsed: 16.224470752s [1mSTEP:[0m Saw pod failure [38;5;243m01/30/23 08:38:21.985[0m Jan 30 08:38:21.986: INFO: Pod "azurefile-volume-tester-dt8kq" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/30/23 08:38:21.986[0m Jan 30 08:38:22.105: INFO: deleting Pod "azurefile-60"/"azurefile-volume-tester-dt8kq" Jan 30 08:38:22.217: INFO: Pod azurefile-volume-tester-dt8kq has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied. At line:1 char:22 + ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 49 lines ... Jan 30 08:38:27.349: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-x6dgf] to have phase Bound Jan 30 08:38:27.458: INFO: PersistentVolumeClaim pvc-x6dgf found and phase=Bound (108.950105ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:27.458[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:27.565[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:27.674[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:27.674[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:38:27.786[0m Jan 30 08:38:27.787: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l49kl" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:38:27.894: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 107.810986ms Jan 30 08:38:30.005: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218083573s Jan 30 08:38:32.010: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223254824s Jan 30 08:38:34.011: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224919902s Jan 30 08:38:36.010: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=true. Elapsed: 8.223531306s Jan 30 08:38:38.012: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=true. Elapsed: 10.225080377s Jan 30 08:38:40.014: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=true. Elapsed: 12.227440016s Jan 30 08:38:42.010: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=false. Elapsed: 14.223519079s Jan 30 08:38:44.011: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.224922023s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:38:44.011[0m Jan 30 08:38:44.012: INFO: Pod "azurefile-volume-tester-l49kl" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:38:44.012[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:38:44.012[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:38:44.122[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:38:44.122[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:38:44.233[0m Jan 30 08:38:44.233: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jg294] to have phase Bound Jan 30 08:38:44.340: INFO: PersistentVolumeClaim pvc-jg294 found and phase=Bound (107.43935ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:44.34[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:44.45[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:44.558[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:44.558[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:38:44.669[0m Jan 30 08:38:44.669: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l5wk6" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:38:44.776: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Pending", Reason="", readiness=false. Elapsed: 107.48376ms Jan 30 08:38:46.892: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.223212426s Jan 30 08:38:48.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223793952s Jan 30 08:38:50.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=true. Elapsed: 6.224639877s Jan 30 08:38:52.894: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=true. Elapsed: 8.225453292s Jan 30 08:38:54.894: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=true. Elapsed: 10.224824509s Jan 30 08:38:56.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=false. Elapsed: 12.224016035s Jan 30 08:38:58.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.224429366s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:38:58.893[0m Jan 30 08:38:58.893: INFO: Pod "azurefile-volume-tester-l5wk6" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:38:58.893[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:38:58.894[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:38:59.014[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:38:59.014[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:38:59.128[0m Jan 30 08:38:59.128: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-2wgwg] to have phase Bound Jan 30 08:38:59.237: INFO: PersistentVolumeClaim pvc-2wgwg found and phase=Bound (109.11934ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:59.237[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:59.346[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:59.455[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:59.455[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:38:59.569[0m Jan 30 08:38:59.569: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-w886w" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:38:59.678: INFO: Pod "azurefile-volume-tester-w886w": Phase="Pending", Reason="", readiness=false. Elapsed: 108.702503ms Jan 30 08:39:01.794: INFO: Pod "azurefile-volume-tester-w886w": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224871137s Jan 30 08:39:03.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Pending", Reason="", readiness=false. Elapsed: 4.226865245s Jan 30 08:39:05.795: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=true. Elapsed: 6.225446773s Jan 30 08:39:07.795: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=true. Elapsed: 8.225881979s Jan 30 08:39:09.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=true. Elapsed: 10.226554583s Jan 30 08:39:11.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=false. Elapsed: 12.22677218s Jan 30 08:39:13.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.226850083s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:13.796[0m Jan 30 08:39:13.796: INFO: Pod "azurefile-volume-tester-w886w" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:39:13.796[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:39:13.796[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:39:13.91[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:39:13.911[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:39:14.025[0m Jan 30 08:39:14.025: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6h5f2] to have phase Bound Jan 30 08:39:14.134: INFO: PersistentVolumeClaim pvc-6h5f2 found and phase=Bound (108.893221ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:39:14.134[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:39:14.243[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:39:14.351[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:39:14.351[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:39:14.467[0m Jan 30 08:39:14.467: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7svqt" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:39:14.576: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Pending", Reason="", readiness=false. Elapsed: 109.752548ms Jan 30 08:39:16.693: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.226498873s Jan 30 08:39:18.695: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22832032s Jan 30 08:39:20.693: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=true. Elapsed: 6.226500943s Jan 30 08:39:22.694: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=true. Elapsed: 8.227094254s Jan 30 08:39:24.693: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=true. Elapsed: 10.22678101s Jan 30 08:39:26.704: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=false. Elapsed: 12.237235712s Jan 30 08:39:28.694: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.227585085s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:28.694[0m Jan 30 08:39:28.695: INFO: Pod "azurefile-volume-tester-7svqt" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:39:28.695[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:39:28.695[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:39:28.808[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:39:28.808[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:39:28.919[0m Jan 30 08:39:28.919: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-fglvn] to have phase Bound Jan 30 08:39:29.028: INFO: PersistentVolumeClaim pvc-fglvn found and phase=Bound (109.025642ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:39:29.028[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:39:29.137[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:39:29.246[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:39:29.246[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:39:29.366[0m Jan 30 08:39:29.366: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-hwmtm" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:39:29.475: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Pending", Reason="", readiness=false. Elapsed: 108.27302ms Jan 30 08:39:31.591: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224346754s Jan 30 08:39:33.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22613006s Jan 30 08:39:35.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=true. Elapsed: 6.226404332s Jan 30 08:39:37.598: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=true. Elapsed: 8.231123976s Jan 30 08:39:39.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=true. Elapsed: 10.226259301s Jan 30 08:39:41.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=false. Elapsed: 12.226661865s Jan 30 08:39:43.592: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.225764345s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:43.592[0m Jan 30 08:39:43.592: INFO: Pod "azurefile-volume-tester-hwmtm" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:39:43.592[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:39:43.592[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:39:43.705[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:39:43.706[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:39:43.817[0m Jan 30 08:39:43.817: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-zj5th] to have phase Bound Jan 30 08:39:43.926: INFO: PersistentVolumeClaim pvc-zj5th found and phase=Bound (108.620998ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:39:43.926[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:39:44.035[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:39:44.144[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:39:44.144[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:39:44.262[0m Jan 30 08:39:44.262: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-s94gk" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:39:44.371: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Pending", Reason="", readiness=false. Elapsed: 108.53811ms Jan 30 08:39:46.487: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224629837s Jan 30 08:39:48.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.225779573s Jan 30 08:39:50.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=true. Elapsed: 6.225660706s Jan 30 08:39:52.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=true. Elapsed: 8.225788663s Jan 30 08:39:54.489: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=true. Elapsed: 10.22685747s Jan 30 08:39:56.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=false. Elapsed: 12.225527199s Jan 30 08:39:58.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.225822599s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:58.488[0m Jan 30 08:39:58.488: INFO: Pod "azurefile-volume-tester-s94gk" satisfied condition "Succeeded or Failed" Jan 30 08:39:58.488: INFO: deleting Pod "azurefile-1181"/"azurefile-volume-tester-s94gk" Jan 30 08:39:58.612: INFO: Pod azurefile-volume-tester-s94gk has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-s94gk in namespace azurefile-1181 [38;5;243m01/30/23 08:39:58.612[0m Jan 30 08:39:58.744: INFO: deleting PVC "azurefile-1181"/"pvc-zj5th" Jan 30 08:39:58.744: INFO: Deleting PersistentVolumeClaim "pvc-zj5th" ... skipping 94 lines ... Jan 30 08:38:27.349: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-x6dgf] to have phase Bound Jan 30 08:38:27.458: INFO: PersistentVolumeClaim pvc-x6dgf found and phase=Bound (108.950105ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:27.458[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:27.565[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:27.674[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:27.674[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:38:27.786[0m Jan 30 08:38:27.787: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l49kl" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:38:27.894: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 107.810986ms Jan 30 08:38:30.005: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218083573s Jan 30 08:38:32.010: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223254824s Jan 30 08:38:34.011: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.224919902s Jan 30 08:38:36.010: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=true. Elapsed: 8.223531306s Jan 30 08:38:38.012: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=true. Elapsed: 10.225080377s Jan 30 08:38:40.014: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=true. Elapsed: 12.227440016s Jan 30 08:38:42.010: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Running", Reason="", readiness=false. Elapsed: 14.223519079s Jan 30 08:38:44.011: INFO: Pod "azurefile-volume-tester-l49kl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.224922023s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:38:44.011[0m Jan 30 08:38:44.012: INFO: Pod "azurefile-volume-tester-l49kl" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:38:44.012[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:38:44.012[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:38:44.122[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:38:44.122[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:38:44.233[0m Jan 30 08:38:44.233: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jg294] to have phase Bound Jan 30 08:38:44.340: INFO: PersistentVolumeClaim pvc-jg294 found and phase=Bound (107.43935ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:44.34[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:44.45[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:44.558[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:44.558[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:38:44.669[0m Jan 30 08:38:44.669: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-l5wk6" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:38:44.776: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Pending", Reason="", readiness=false. Elapsed: 107.48376ms Jan 30 08:38:46.892: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.223212426s Jan 30 08:38:48.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.223793952s Jan 30 08:38:50.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=true. Elapsed: 6.224639877s Jan 30 08:38:52.894: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=true. Elapsed: 8.225453292s Jan 30 08:38:54.894: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=true. Elapsed: 10.224824509s Jan 30 08:38:56.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Running", Reason="", readiness=false. Elapsed: 12.224016035s Jan 30 08:38:58.893: INFO: Pod "azurefile-volume-tester-l5wk6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.224429366s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:38:58.893[0m Jan 30 08:38:58.893: INFO: Pod "azurefile-volume-tester-l5wk6" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:38:58.893[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:38:58.894[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:38:59.014[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:38:59.014[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:38:59.128[0m Jan 30 08:38:59.128: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-2wgwg] to have phase Bound Jan 30 08:38:59.237: INFO: PersistentVolumeClaim pvc-2wgwg found and phase=Bound (109.11934ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:38:59.237[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:38:59.346[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:38:59.455[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:38:59.455[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:38:59.569[0m Jan 30 08:38:59.569: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-w886w" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:38:59.678: INFO: Pod "azurefile-volume-tester-w886w": Phase="Pending", Reason="", readiness=false. Elapsed: 108.702503ms Jan 30 08:39:01.794: INFO: Pod "azurefile-volume-tester-w886w": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224871137s Jan 30 08:39:03.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Pending", Reason="", readiness=false. Elapsed: 4.226865245s Jan 30 08:39:05.795: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=true. Elapsed: 6.225446773s Jan 30 08:39:07.795: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=true. Elapsed: 8.225881979s Jan 30 08:39:09.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=true. Elapsed: 10.226554583s Jan 30 08:39:11.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Running", Reason="", readiness=false. Elapsed: 12.22677218s Jan 30 08:39:13.796: INFO: Pod "azurefile-volume-tester-w886w": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.226850083s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:13.796[0m Jan 30 08:39:13.796: INFO: Pod "azurefile-volume-tester-w886w" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:39:13.796[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:39:13.796[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:39:13.91[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:39:13.911[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:39:14.025[0m Jan 30 08:39:14.025: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6h5f2] to have phase Bound Jan 30 08:39:14.134: INFO: PersistentVolumeClaim pvc-6h5f2 found and phase=Bound (108.893221ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:39:14.134[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:39:14.243[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:39:14.351[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:39:14.351[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:39:14.467[0m Jan 30 08:39:14.467: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7svqt" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:39:14.576: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Pending", Reason="", readiness=false. Elapsed: 109.752548ms Jan 30 08:39:16.693: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.226498873s Jan 30 08:39:18.695: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22832032s Jan 30 08:39:20.693: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=true. Elapsed: 6.226500943s Jan 30 08:39:22.694: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=true. Elapsed: 8.227094254s Jan 30 08:39:24.693: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=true. Elapsed: 10.22678101s Jan 30 08:39:26.704: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Running", Reason="", readiness=false. Elapsed: 12.237235712s Jan 30 08:39:28.694: INFO: Pod "azurefile-volume-tester-7svqt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.227585085s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:28.694[0m Jan 30 08:39:28.695: INFO: Pod "azurefile-volume-tester-7svqt" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:39:28.695[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:39:28.695[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:39:28.808[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:39:28.808[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:39:28.919[0m Jan 30 08:39:28.919: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-fglvn] to have phase Bound Jan 30 08:39:29.028: INFO: PersistentVolumeClaim pvc-fglvn found and phase=Bound (109.025642ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:39:29.028[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:39:29.137[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:39:29.246[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:39:29.246[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:39:29.366[0m Jan 30 08:39:29.366: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-hwmtm" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:39:29.475: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Pending", Reason="", readiness=false. Elapsed: 108.27302ms Jan 30 08:39:31.591: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224346754s Jan 30 08:39:33.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22613006s Jan 30 08:39:35.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=true. Elapsed: 6.226404332s Jan 30 08:39:37.598: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=true. Elapsed: 8.231123976s Jan 30 08:39:39.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=true. Elapsed: 10.226259301s Jan 30 08:39:41.593: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Running", Reason="", readiness=false. Elapsed: 12.226661865s Jan 30 08:39:43.592: INFO: Pod "azurefile-volume-tester-hwmtm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.225764345s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:43.592[0m Jan 30 08:39:43.592: INFO: Pod "azurefile-volume-tester-hwmtm" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m01/30/23 08:39:43.592[0m [1mSTEP:[0m creating a PV [38;5;243m01/30/23 08:39:43.592[0m [1mSTEP:[0m setting up the PVC [38;5;243m01/30/23 08:39:43.705[0m [1mSTEP:[0m creating a PVC [38;5;243m01/30/23 08:39:43.706[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/30/23 08:39:43.817[0m Jan 30 08:39:43.817: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-zj5th] to have phase Bound Jan 30 08:39:43.926: INFO: PersistentVolumeClaim pvc-zj5th found and phase=Bound (108.620998ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:39:43.926[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:39:44.035[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:39:44.144[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:39:44.144[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:39:44.262[0m Jan 30 08:39:44.262: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-s94gk" in namespace "azurefile-1181" to be "Succeeded or Failed" Jan 30 08:39:44.371: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Pending", Reason="", readiness=false. Elapsed: 108.53811ms Jan 30 08:39:46.487: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224629837s Jan 30 08:39:48.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.225779573s Jan 30 08:39:50.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=true. Elapsed: 6.225660706s Jan 30 08:39:52.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=true. Elapsed: 8.225788663s Jan 30 08:39:54.489: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=true. Elapsed: 10.22685747s Jan 30 08:39:56.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Running", Reason="", readiness=false. Elapsed: 12.225527199s Jan 30 08:39:58.488: INFO: Pod "azurefile-volume-tester-s94gk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.225822599s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:39:58.488[0m Jan 30 08:39:58.488: INFO: Pod "azurefile-volume-tester-s94gk" satisfied condition "Succeeded or Failed" Jan 30 08:39:58.488: INFO: deleting Pod "azurefile-1181"/"azurefile-volume-tester-s94gk" Jan 30 08:39:58.612: INFO: Pod azurefile-volume-tester-s94gk has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-s94gk in namespace azurefile-1181 [38;5;243m01/30/23 08:39:58.612[0m Jan 30 08:39:58.744: INFO: deleting PVC "azurefile-1181"/"pvc-zj5th" Jan 30 08:39:58.744: INFO: Deleting PersistentVolumeClaim "pvc-zj5th" ... skipping 174 lines ... Jan 30 08:40:12.900: INFO: PersistentVolumeClaim pvc-6kzml found but phase is Pending instead of Bound. Jan 30 08:40:15.009: INFO: PersistentVolumeClaim pvc-6kzml found and phase=Bound (2.218132249s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:40:15.009[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:40:15.118[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:40:15.228[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:40:15.228[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:40:15.341[0m Jan 30 08:40:15.341: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-kjfz8" in namespace "azurefile-1040" to be "Succeeded or Failed" Jan 30 08:40:15.449: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 108.55921ms Jan 30 08:40:17.558: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217623656s Jan 30 08:40:19.568: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.226861144s Jan 30 08:40:21.566: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.225336536s Jan 30 08:40:23.567: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=true. Elapsed: 8.226671633s Jan 30 08:40:25.568: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=true. Elapsed: 10.226992955s Jan 30 08:40:27.566: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=true. Elapsed: 12.225689625s Jan 30 08:40:29.568: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=false. Elapsed: 14.226969349s Jan 30 08:40:31.566: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.225567262s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:40:31.566[0m Jan 30 08:40:31.567: INFO: Pod "azurefile-volume-tester-kjfz8" satisfied condition "Succeeded or Failed" Jan 30 08:40:31.567: INFO: deleting Pod "azurefile-1040"/"azurefile-volume-tester-kjfz8" Jan 30 08:40:31.684: INFO: Pod azurefile-volume-tester-kjfz8 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-kjfz8 in namespace azurefile-1040 [38;5;243m01/30/23 08:40:31.684[0m Jan 30 08:40:31.811: INFO: deleting PVC "azurefile-1040"/"pvc-6kzml" Jan 30 08:40:31.811: INFO: Deleting PersistentVolumeClaim "pvc-6kzml" ... skipping 27 lines ... Jan 30 08:40:12.900: INFO: PersistentVolumeClaim pvc-6kzml found but phase is Pending instead of Bound. Jan 30 08:40:15.009: INFO: PersistentVolumeClaim pvc-6kzml found and phase=Bound (2.218132249s) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:40:15.009[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:40:15.118[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:40:15.228[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:40:15.228[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:40:15.341[0m Jan 30 08:40:15.341: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-kjfz8" in namespace "azurefile-1040" to be "Succeeded or Failed" Jan 30 08:40:15.449: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 108.55921ms Jan 30 08:40:17.558: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217623656s Jan 30 08:40:19.568: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.226861144s Jan 30 08:40:21.566: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.225336536s Jan 30 08:40:23.567: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=true. Elapsed: 8.226671633s Jan 30 08:40:25.568: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=true. Elapsed: 10.226992955s Jan 30 08:40:27.566: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=true. Elapsed: 12.225689625s Jan 30 08:40:29.568: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Running", Reason="", readiness=false. Elapsed: 14.226969349s Jan 30 08:40:31.566: INFO: Pod "azurefile-volume-tester-kjfz8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.225567262s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:40:31.566[0m Jan 30 08:40:31.567: INFO: Pod "azurefile-volume-tester-kjfz8" satisfied condition "Succeeded or Failed" Jan 30 08:40:31.567: INFO: deleting Pod "azurefile-1040"/"azurefile-volume-tester-kjfz8" Jan 30 08:40:31.684: INFO: Pod azurefile-volume-tester-kjfz8 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-kjfz8 in namespace azurefile-1040 [38;5;243m01/30/23 08:40:31.684[0m Jan 30 08:40:31.811: INFO: deleting PVC "azurefile-1040"/"pvc-6kzml" Jan 30 08:40:31.811: INFO: Deleting PersistentVolumeClaim "pvc-6kzml" ... skipping 27 lines ... Jan 30 08:40:35.860: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-mdhx4] to have phase Bound Jan 30 08:40:35.968: INFO: PersistentVolumeClaim pvc-mdhx4 found and phase=Bound (108.389301ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:40:35.968[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:40:36.077[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:40:36.186[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:40:36.186[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:40:36.298[0m Jan 30 08:40:36.298: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-w7w59" in namespace "azurefile-6443" to be "Succeeded or Failed" Jan 30 08:40:36.408: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 110.048127ms Jan 30 08:40:38.519: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220994214s Jan 30 08:40:40.527: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 4.228985715s Jan 30 08:40:42.526: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 6.228454054s Jan 30 08:40:44.526: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=true. Elapsed: 8.228211326s Jan 30 08:40:46.525: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=true. Elapsed: 10.226843958s Jan 30 08:40:48.525: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=true. Elapsed: 12.227595519s Jan 30 08:40:50.524: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=false. Elapsed: 14.226511169s Jan 30 08:40:52.525: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.226943572s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:40:52.525[0m Jan 30 08:40:52.525: INFO: Pod "azurefile-volume-tester-w7w59" satisfied condition "Succeeded or Failed" Jan 30 08:40:52.525: INFO: deleting Pod "azurefile-6443"/"azurefile-volume-tester-w7w59" Jan 30 08:40:52.647: INFO: Pod azurefile-volume-tester-w7w59 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-w7w59 in namespace azurefile-6443 [38;5;243m01/30/23 08:40:52.647[0m Jan 30 08:40:52.774: INFO: deleting PVC "azurefile-6443"/"pvc-mdhx4" Jan 30 08:40:52.774: INFO: Deleting PersistentVolumeClaim "pvc-mdhx4" ... skipping 31 lines ... Jan 30 08:40:35.860: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-mdhx4] to have phase Bound Jan 30 08:40:35.968: INFO: PersistentVolumeClaim pvc-mdhx4 found and phase=Bound (108.389301ms) [1mSTEP:[0m checking the PVC [38;5;243m01/30/23 08:40:35.968[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/30/23 08:40:36.077[0m [1mSTEP:[0m checking the PV [38;5;243m01/30/23 08:40:36.186[0m [1mSTEP:[0m deploying the pod [38;5;243m01/30/23 08:40:36.186[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/30/23 08:40:36.298[0m Jan 30 08:40:36.298: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-w7w59" in namespace "azurefile-6443" to be "Succeeded or Failed" Jan 30 08:40:36.408: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 110.048127ms Jan 30 08:40:38.519: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220994214s Jan 30 08:40:40.527: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 4.228985715s Jan 30 08:40:42.526: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Pending", Reason="", readiness=false. Elapsed: 6.228454054s Jan 30 08:40:44.526: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=true. Elapsed: 8.228211326s Jan 30 08:40:46.525: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=true. Elapsed: 10.226843958s Jan 30 08:40:48.525: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=true. Elapsed: 12.227595519s Jan 30 08:40:50.524: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Running", Reason="", readiness=false. Elapsed: 14.226511169s Jan 30 08:40:52.525: INFO: Pod "azurefile-volume-tester-w7w59": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.226943572s [1mSTEP:[0m Saw pod success [38;5;243m01/30/23 08:40:52.525[0m Jan 30 08:40:52.525: INFO: Pod "azurefile-volume-tester-w7w59" satisfied condition "Succeeded or Failed" Jan 30 08:40:52.525: INFO: deleting Pod "azurefile-6443"/"azurefile-volume-tester-w7w59" Jan 30 08:40:52.647: INFO: Pod azurefile-volume-tester-w7w59 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-w7w59 in namespace azurefile-6443 [38;5;243m01/30/23 08:40:52.647[0m Jan 30 08:40:52.774: INFO: deleting PVC "azurefile-6443"/"pvc-mdhx4" Jan 30 08:40:52.774: INFO: Deleting PersistentVolumeClaim "pvc-mdhx4" ... skipping 77 lines ... Streaming logs below: I0130 08:19:35.907852 1 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test I0130 08:19:35.907956 1 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0130 08:19:35.908278 1 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I0130 08:19:35.964924 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 56 milliseconds I0130 08:19:35.965216 1 azure.go:87] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0130 08:19:35.965226 1 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:19:35.965232 1 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0130 08:19:35.965280 1 azure.go:110] read cloud config from file: /etc/kubernetes/azure.json successfully I0130 08:19:35.966213 1 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:19:35.966253 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:19:35.966321 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0130 08:19:35.966374 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0130 08:19:35.966456 1 azure.go:1010] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0130 08:19:35.966470 1 azure.go:140] disable UseInstanceMetadata for controller server I0130 08:19:35.966475 1 azure.go:143] starting controller server... I0130 08:19:35.966490 1 azurefile.go:304] cloud: AzurePublicCloud, location: westeurope, rg: capz-e7g6lu, VnetName: capz-e7g6lu-vnet, VnetResourceGroup: capz-e7g6lu, SubnetName: node-subnet I0130 08:19:35.970139 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount1860059089' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount1860059089: must be superuser to unmount. I0130 08:19:35.970162 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0130 08:19:35.970219 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME I0130 08:19:35.970225 1 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0130 08:19:35.970229 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0130 08:19:35.970233 1 driver.go:93] Enabling controller service capability: EXPAND_VOLUME I0130 08:19:35.970236 1 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER ... skipping 447 lines ... Pragma: no-cache Content-Type: application/json; charset=utf-8 X-Ms-Request-Id: 7658578c-01ba-4474-8fb6-1a1d50fbd5cb X-Ms-Routing-Request-Id: WESTEUROPE:20230130T082036Z:7658578c-01ba-4474-8fb6-1a1d50fbd5cb Strict-Transport-Security: max-age=31536000; includeSubDomains I0130 08:20:36.587907 1 util.go:124] Send.sendRequest got response with ContentLength 250, StatusCode 404 and responseBody length 250 I0130 08:20:36.587976 1 azure_privatednsclient.go:215] Received error in privatednszone.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net, error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:20:36.588146 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.019923872 request="private_dns_zones_get" resource_group="capz-e7g6lu" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I0130 08:20:36.588166 1 azure_storageaccount.go:239] get private dns zone privatelink.file.core.windows.net returned with Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:20:36.588186 1 azure_storageaccount.go:464] Creating private dns zone(privatelink.file.core.windows.net) in resourceGroup (capz-e7g6lu) (2023-01-30T08:20:36.5883000Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 User-Agent: Go/go1.19.5 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test Authorization: **REDACTED** Content-Type: application/json; charset=utf-8 (2023-01-30T08:20:36.5883519Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 ... skipping 140 lines ... X-Ms-Failure-Cause: gateway X-Content-Type-Options: nosniff Date: Mon, 30 Jan 2023 08:21:07 GMT Content-Length: 296 Cache-Control: no-cache I0130 08:21:08.299935 1 util.go:124] Send.sendRequest got response with ContentLength 296, StatusCode 404 and responseBody length 296 I0130 08:21:08.299950 1 azure_virtualnetworklinksclient.go:212] Received error in virtualnetworklink.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink, error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:21:08.300036 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.054038339 request="virtual_network_links_get" resource_group="capz-e7g6lu" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I0130 08:21:08.300054 1 azure_storageaccount.go:249] get virtual link for vnet(capz-e7g6lu-vnet) and DNS Zone(privatelink.file.core.windows.net) returned with Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink' under resource group 'capz-e7g6lu' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I0130 08:21:08.300060 1 azure_storageaccount.go:478] Creating virtual link for vnet(capz-e7g6lu-vnet-vnetlink) and DNS Zone(privatelink.file.core.windows.net) in resourceGroup(capz-e7g6lu) (2023-01-30T08:21:08.3001522Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink?api-version=2020-06-01 User-Agent: Go/go1.19.5 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-96a2ca02f36f8e1cb5b590f772c52ba00ac89296 e2e-test Authorization: **REDACTED** Content-Type: application/json; charset=utf-8 (2023-01-30T08:21:08.3001892Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-e7g6lu/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/capz-e7g6lu-vnet-vnetlink?api-version=2020-06-01 ... skipping 4956 lines ... Platform: linux/amd64 Streaming logs below: I0130 08:37:47.420404 1 azurefile.go:299] driver userAgent: file.csi.azure.com/v1.25.0 I0130 08:37:47.420496 1 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0130 08:37:47.420757 1 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I0130 08:37:47.431855 1 azure.go:87] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0130 08:37:47.431874 1 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:37:47.431880 1 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0130 08:37:47.431899 1 azure.go:110] read cloud config from file: /etc/kubernetes/azure.json successfully I0130 08:37:47.432342 1 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:37:47.432376 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:37:47.432433 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 42 lines ... Git Commit: f25f97e4b05828ce0962ffc15bfce693e0a731b6 Go Version: go1.19.4 Platform: windows/amd64 Streaming logs below: I0130 08:37:49.547326 6352 azurefile.go:299] driver userAgent: file.csi.azure.com/v1.25.0 W0130 08:37:49.549839 6352 azure.go:73] get kubeconfig(C:\\k\\config) failed with error: CreateFile C:\\k\\config: The system cannot find the file specified. I0130 08:37:49.550822 6352 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:37:49.550859 6352 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0130 08:37:49.551077 6352 azure.go:110] read cloud config from file: C:\k\azure.json successfully I0130 08:37:49.551940 6352 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:37:49.552564 6352 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:37:49.554546 6352 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 40 lines ... Git Commit: f25f97e4b05828ce0962ffc15bfce693e0a731b6 Go Version: go1.19.4 Platform: windows/amd64 Streaming logs below: I0130 08:37:49.546255 8300 azurefile.go:299] driver userAgent: file.csi.azure.com/v1.25.0 W0130 08:37:49.547257 8300 azure.go:73] get kubeconfig(C:\\k\\config) failed with error: CreateFile C:\\k\\config: The system cannot find the file specified. I0130 08:37:49.547756 8300 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I0130 08:37:49.547756 8300 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0130 08:37:49.547756 8300 azure.go:110] read cloud config from file: C:\k\azure.json successfully I0130 08:37:49.549247 8300 azure_auth.go:253] Using AzurePublicCloud environment I0130 08:37:49.549758 8300 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0130 08:37:49.551251 8300 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 41 lines ... I0130 08:37:50.165269 8300 utils.go:83] GRPC response: {"name":"file.csi.azure.com","vendor_version":"v1.25.0"} I0130 08:37:52.129774 8300 utils.go:76] GRPC call: /csi.v1.Node/NodeGetInfo I0130 08:37:52.129774 8300 utils.go:77] GRPC request: {} I0130 08:37:52.130276 8300 utils.go:83] GRPC response: {"node_id":"capz-e7g6-zssl6"} I0130 08:38:05.991422 8300 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume I0130 08:38:05.991422 8300 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-60-file.csi.azure.com-preprovsioned-pv-2q4s7\\globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_id":"capz-e7g6lu#f614364cca2934d1f8f84e3#pre-provisioned-readonly##pre-provisioned-readonly#azurefile-60"} W0130 08:38:05.992912 8300 azurefile.go:668] GetStorageAccountFromSecret(azure-storage-account-f614364cca2934d1f8f84e3-secret, azurefile-60) failed with error: could not get account key from secret(azure-storage-account-f614364cca2934d1f8f84e3-secret): KubeClient is nil I0130 08:38:05.992912 8300 azurefile.go:670] use cluster identity to get account key from (0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e, capz-e7g6lu, f614364cca2934d1f8f84e3) I0130 08:38:06.538419 8300 nodeserver.go:302] cifsMountPath(\var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-60-file.csi.azure.com-preprovsioned-pv-2q4s7\globalmount) fstype() volumeID(capz-e7g6lu#f614364cca2934d1f8f84e3#pre-provisioned-readonly##pre-provisioned-readonly#azurefile-60) context(map[]) mountflags([]) mountOptions([AZURE\f614364cca2934d1f8f84e3]) volumeMountGroup() I0130 08:38:06.538419 8300 safe_mounter_windows.go:155] IsLikelyNotMountPoint: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-60-file.csi.azure.com-preprovsioned-pv-2q4s7\globalmount I0130 08:38:06.538419 8300 safe_mounter_windows.go:212] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-60-file.csi.azure.com-preprovsioned-pv-2q4s7\globalmount I0130 08:38:06.541414 8300 safe_mounter_windows.go:212] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-60-file.csi.azure.com-preprovsioned-pv-2q4s7\globalmount I0130 08:38:06.542413 8300 azure_common_windows.go:52] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-60-file.csi.azure.com-preprovsioned-pv-2q4s7\globalmount ... skipping 341 lines ... I0130 08:40:51.143626 8300 nodeserver.go:393] NodeUnstageVolume: CleanupMountPoint volume capz-e7g6lu#f614364cca2934d1f8f84e3#pre-provisioned-provided-credentials##pre-provisioned-provided-credentials#azurefile-6443 on \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-6443-file.csi.azure.com-preprovsioned-pv-8j798\proxy-mount I0130 08:40:51.143626 8300 safe_mounter_windows.go:125] Remove directory: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-6443-file.csi.azure.com-preprovsioned-pv-8j798\proxy-mount I0130 08:40:51.144123 8300 nodeserver.go:397] NodeUnstageVolume: unmount volume capz-e7g6lu#f614364cca2934d1f8f84e3#pre-provisioned-provided-credentials##pre-provisioned-provided-credentials#azurefile-6443 on \var\lib\kubelet\plugins\kubernetes.io\csi\pv\azurefile-6443-file.csi.azure.com-preprovsioned-pv-8j798\globalmount successfully I0130 08:40:51.144123 8300 utils.go:83] GRPC response: {} I0130 08:40:58.033889 8300 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume I0130 08:40:58.033889 8300 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1\\globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["dir_mode=0777","file_mode=0777","mfsymlinks","cache=strict","nosharesock","actimeo=30"]}},"access_mode":{"mode":5}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1","csi.storage.k8s.io/pvc/name":"pvc-azurefile","csi.storage.k8s.io/pvc/namespace":"default","secretnamespace":"default","skuName":"Premium_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1675066776049-8081-file.csi.azure.com"},"volume_id":"capz-e7g6lu#f2c6d0e932a494dc4b4ce63#pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1###default"} W0130 08:40:58.034894 8300 azurefile.go:668] GetStorageAccountFromSecret(azure-storage-account-f2c6d0e932a494dc4b4ce63-secret, default) failed with error: could not get account key from secret(azure-storage-account-f2c6d0e932a494dc4b4ce63-secret): KubeClient is nil I0130 08:40:58.034894 8300 azurefile.go:670] use cluster identity to get account key from (0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e, capz-e7g6lu, f2c6d0e932a494dc4b4ce63) I0130 08:40:58.239543 8300 nodeserver.go:302] cifsMountPath(\var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1\globalmount) fstype() volumeID(capz-e7g6lu#f2c6d0e932a494dc4b4ce63#pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1###default) context(map[csi.storage.k8s.io/pv/name:pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1 csi.storage.k8s.io/pvc/name:pvc-azurefile csi.storage.k8s.io/pvc/namespace:default secretnamespace:default skuName:Premium_LRS storage.kubernetes.io/csiProvisionerIdentity:1675066776049-8081-file.csi.azure.com]) mountflags([dir_mode=0777 file_mode=0777 mfsymlinks cache=strict nosharesock actimeo=30]) mountOptions([AZURE\f2c6d0e932a494dc4b4ce63]) volumeMountGroup() I0130 08:40:58.239543 8300 safe_mounter_windows.go:155] IsLikelyNotMountPoint: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1\globalmount I0130 08:40:58.239543 8300 safe_mounter_windows.go:212] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1\globalmount I0130 08:40:58.241039 8300 safe_mounter_windows.go:212] Exists path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1\globalmount I0130 08:40:58.241545 8300 azure_common_windows.go:52] Removing path: \var\lib\kubelet\plugins\kubernetes.io\csi\pv\pvc-f40694eb-67e4-4a91-a26e-6cf65fe397d1\globalmount ... skipping 460 lines ... # HELP go_gc_heap_objects_objects Number of objects, live or unswept, occupying heap memory. # TYPE go_gc_heap_objects_objects gauge go_gc_heap_objects_objects 48806 # HELP go_gc_heap_tiny_allocs_objects_total Count of small allocations that are packed together into blocks. These allocations are counted separately from other allocations because each individual allocation is not tracked by the runtime, only their block. Each block is already accounted for in allocs-by-size and frees-by-size. # TYPE go_gc_heap_tiny_allocs_objects_total counter go_gc_heap_tiny_allocs_objects_total 19573 # HELP go_gc_limiter_last_enabled_gc_cycle GC cycle the last time the GC CPU limiter was enabled. This metric is useful for diagnosing the root cause of an out-of-memory error, because the limiter trades memory for CPU time when the GC's CPU time gets too high. This is most likely to occur with use of SetMemoryLimit. The first GC cycle is cycle 1, so a value of 0 indicates that it was never enabled. # TYPE go_gc_limiter_last_enabled_gc_cycle gauge go_gc_limiter_last_enabled_gc_cycle 0 # HELP go_gc_pauses_seconds Distribution individual GC-related stop-the-world pause latencies. # TYPE go_gc_pauses_seconds histogram go_gc_pauses_seconds_bucket{le="9.999999999999999e-10"} 0 go_gc_pauses_seconds_bucket{le="9.999999999999999e-09"} 0 ... skipping 252 lines ... [1mSTEP:[0m GetAccountNumByResourceGroup(capz-e7g6lu) returns 9 accounts [38;5;243m01/30/23 08:41:46.018[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;243m------------------------------[0m [38;5;9m[1mSummarizing 1 Failure:[0m [38;5;9m[FAIL][0m [0mDynamic Provisioning [38;5;243m[38;5;9m[1m[It] should create a statefulset object, write and read to it, delete the pod and write and read to it again [file.csi.azure.com][0m[0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/testsuites.go:1011[0m [38;5;9m[1mRan 22 of 38 Specs in 1986.240 seconds[0m [38;5;9m[1mFAIL![0m -- [38;5;10m[1m21 Passed[0m | [38;5;9m[1m1 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m16 Skipped[0m [38;5;228mYou're using deprecated Ginkgo functionality:[0m [38;5;228m=============================================[0m [38;5;11mSupport for custom reporters has been removed in V2. Please read the documentation linked to below for Ginkgo's new behavior and for a migration path:[0m [1mLearn more at:[0m [38;5;14m[4mhttps://onsi.github.io/ginkgo/MIGRATING_TO_V2#removed-custom-reporters[0m [38;5;243mTo silence deprecations that can be silenced set the following environment variable:[0m [38;5;243mACK_GINKGO_DEPRECATIONS=2.4.0[0m --- FAIL: TestE2E (1986.24s) FAIL FAIL sigs.k8s.io/azurefile-csi-driver/test/e2e 1986.346s FAIL make: *** [Makefile:85: e2e-test] Error 1 NAME STATUS ROLES AGE VERSION INTERNAL-IP EXTERNAL-IP OS-IMAGE KERNEL-VERSION CONTAINER-RUNTIME capz-e7g6-vf7kt Ready <none> 37m v1.23.17-rc.0.5+a3ccd27a5da633 10.1.0.4 <none> Windows Server 2019 Datacenter 10.0.17763.3887 containerd://1.6.15 capz-e7g6-zssl6 Ready <none> 37m v1.23.17-rc.0.5+a3ccd27a5da633 10.1.0.5 <none> Windows Server 2019 Datacenter 10.0.17763.3887 containerd://1.6.15 capz-e7g6lu-control-plane-rfw9w Ready control-plane,master 40m v1.23.17-rc.0.5+a3ccd27a5da633 10.0.0.4 <none> Ubuntu 18.04.6 LTS 5.4.0-1100-azure containerd://1.6.15 NAMESPACE NAME READY STATUS RESTARTS AGE IP NODE NOMINATED NODE READINESS GATES azurefile-9183 azurefile-volume-tester-n8m2l-0 0/1 Terminating 0 7m57s <none> capz-e7g6-zssl6 <none> <none> ... skipping 37 lines ... Jan 30 08:45:34.607: INFO: Collecting logs for Windows node capz-e7g6-vf7kt in cluster capz-e7g6lu in namespace default Jan 30 08:47:13.231: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-e7g6-vf7kt to /logs/artifacts/clusters/capz-e7g6lu/machines/capz-e7g6lu-md-win-687c8f465d-p8kp5/crashdumps.tar Jan 30 08:47:16.807: INFO: Collecting boot logs for AzureMachine capz-e7g6lu-md-win-vf7kt Failed to get logs for Machine capz-e7g6lu-md-win-687c8f465d-p8kp5, Cluster default/capz-e7g6lu: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1 Jan 30 08:47:18.222: INFO: Collecting logs for Windows node capz-e7g6-zssl6 in cluster capz-e7g6lu in namespace default Jan 30 08:49:09.073: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-e7g6-zssl6 to /logs/artifacts/clusters/capz-e7g6lu/machines/capz-e7g6lu-md-win-687c8f465d-qzhrn/crashdumps.tar Jan 30 08:49:12.711: INFO: Collecting boot logs for AzureMachine capz-e7g6lu-md-win-zssl6 Failed to get logs for Machine capz-e7g6lu-md-win-687c8f465d-qzhrn, Cluster default/capz-e7g6lu: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1 Jan 30 08:49:14.186: INFO: Dumping workload cluster default/capz-e7g6lu kube-system pod logs Jan 30 08:49:15.302: INFO: Describing Pod azurefile-9183/azurefile-volume-tester-n8m2l-0 Jan 30 08:49:15.302: INFO: Creating log watcher for controller azurefile-9183/azurefile-volume-tester-n8m2l-0, container volume-tester Jan 30 08:49:15.530: INFO: Creating log watcher for controller calico-apiserver/calico-apiserver-6d868c9f7-2rcbs, container calico-apiserver Jan 30 08:49:15.530: INFO: Describing Pod calico-apiserver/calico-apiserver-6d868c9f7-2rcbs Jan 30 08:49:15.826: INFO: Describing Pod calico-apiserver/calico-apiserver-6d868c9f7-psxx5 ... skipping 73 lines ...