kubernetes-sigs/azurefile-csi-driver PR #1147 pull-azurefile-csi-driver-e2e-windows-containerd #1607362327181529088
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | andyzhangx: test: add unmount volume test |
| Result | FAILURE |
| Tests | 1 failed / 14 succeeded |
| Started | |
| Elapsed | 47m22s |
| Revision | def825a20c994856c3013834a2264732da32ec20 |
| Refs |
1147 |
| job-version | v1.27.0-alpha.0.629+685d639cb5f04c |
| kubetest-version | v20221223-736a4da5ba |
| revision | v1.27.0-alpha.0.629+685d639cb5f04c |
error during make e2e-test: exit status 2
from junit_runner.xml
Filter through log files | View test history on testgrid
kubetest Build
kubetest Check APIReachability
kubetest Deferred TearDown
kubetest DumpClusterLogs
kubetest GetDeployer
kubetest IsUp
kubetest Prepare
kubetest TearDown
kubetest TearDown Previous
kubetest Timeout
kubetest Up
kubetest kubectl version
kubetest list nodes
kubetest test setup
... skipping 106 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 84037 0 --:--:-- --:--:-- --:--:-- 84037 Downloading https://get.helm.sh/helm-v3.10.3-linux-amd64.tar.gz Verifying checksum... Done. Preparing to install helm into /usr/local/bin helm installed into /usr/local/bin/helm docker pull k8sprow.azurecr.io/azurefile-csi:e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d || make container-all push-manifest Error response from daemon: manifest for k8sprow.azurecr.io/azurefile-csi:e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d not found: manifest unknown: manifest tagged by "e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d" 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-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2022-12-26T13:18:23Z -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 2534 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 190 lines ... Dec 26 13:38:23.240: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jfmld] to have phase Bound Dec 26 13:38:23.276: INFO: PersistentVolumeClaim pvc-jfmld found and phase=Bound (36.676758ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:38:23.277[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:38:23.313[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:38:23.351[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:38:23.351[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m12/26/22 13:38:23.392[0m Dec 26 13:38:23.392: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-pg6dh" in namespace "azurefile-8081" to be "Error status code" Dec 26 13:38:23.429: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 37.36664ms Dec 26 13:38:25.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076018903s Dec 26 13:38:27.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075241473s Dec 26 13:38:29.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.075423371s Dec 26 13:38:31.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.075872918s Dec 26 13:38:33.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.076160714s ... skipping 3 lines ... Dec 26 13:38:41.469: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 18.076835196s Dec 26 13:38:43.470: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 20.077769076s Dec 26 13:38:45.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 22.074870436s Dec 26 13:38:47.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 24.076554182s Dec 26 13:38:49.469: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 26.076799295s Dec 26 13:38:51.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=false. Elapsed: 28.07588733s Dec 26 13:38:53.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Failed", Reason="", readiness=false. Elapsed: 30.074911459s [1mSTEP:[0m Saw pod failure [38;5;243m12/26/22 13:38:53.467[0m Dec 26 13:38:53.467: INFO: Pod "azurefile-volume-tester-pg6dh" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m12/26/22 13:38:53.467[0m Dec 26 13:38:53.545: INFO: deleting Pod "azurefile-8081"/"azurefile-volume-tester-pg6dh" Dec 26 13:38:53.587: INFO: Pod azurefile-volume-tester-pg6dh 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 73 lines ... Dec 26 13:38:23.240: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jfmld] to have phase Bound Dec 26 13:38:23.276: INFO: PersistentVolumeClaim pvc-jfmld found and phase=Bound (36.676758ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:38:23.277[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:38:23.313[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:38:23.351[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:38:23.351[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m12/26/22 13:38:23.392[0m Dec 26 13:38:23.392: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-pg6dh" in namespace "azurefile-8081" to be "Error status code" Dec 26 13:38:23.429: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 37.36664ms Dec 26 13:38:25.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076018903s Dec 26 13:38:27.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075241473s Dec 26 13:38:29.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.075423371s Dec 26 13:38:31.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.075872918s Dec 26 13:38:33.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.076160714s ... skipping 3 lines ... Dec 26 13:38:41.469: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 18.076835196s Dec 26 13:38:43.470: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 20.077769076s Dec 26 13:38:45.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 22.074870436s Dec 26 13:38:47.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 24.076554182s Dec 26 13:38:49.469: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=true. Elapsed: 26.076799295s Dec 26 13:38:51.468: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Running", Reason="", readiness=false. Elapsed: 28.07588733s Dec 26 13:38:53.467: INFO: Pod "azurefile-volume-tester-pg6dh": Phase="Failed", Reason="", readiness=false. Elapsed: 30.074911459s [1mSTEP:[0m Saw pod failure [38;5;243m12/26/22 13:38:53.467[0m Dec 26 13:38:53.467: INFO: Pod "azurefile-volume-tester-pg6dh" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m12/26/22 13:38:53.467[0m Dec 26 13:38:53.545: INFO: deleting Pod "azurefile-8081"/"azurefile-volume-tester-pg6dh" Dec 26 13:38:53.587: INFO: Pod azurefile-volume-tester-pg6dh 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 ... Dec 26 13:38:55.913: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-b8r6h] to have phase Bound Dec 26 13:38:55.950: INFO: PersistentVolumeClaim pvc-b8r6h found and phase=Bound (36.651631ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:38:55.95[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:38:55.988[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:38:56.025[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:38:56.025[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:38:56.064[0m Dec 26 13:38:56.064: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-2vg56" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:38:56.101: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 36.687846ms Dec 26 13:38:58.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074561167s Dec 26 13:39:00.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075499206s Dec 26 13:39:02.141: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 6.07676769s Dec 26 13:39:04.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 8.074900799s Dec 26 13:39:06.141: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 10.076525323s ... skipping 5 lines ... Dec 26 13:39:18.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=true. Elapsed: 22.076120981s Dec 26 13:39:20.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=true. Elapsed: 24.076112814s Dec 26 13:39:22.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=true. Elapsed: 26.075475243s Dec 26 13:39:24.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=false. Elapsed: 28.075296504s Dec 26 13:39:26.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Succeeded", Reason="", readiness=false. Elapsed: 30.074466953s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:39:26.139[0m Dec 26 13:39:26.139: INFO: Pod "azurefile-volume-tester-2vg56" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:39:26.139[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:39:26.139[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:39:26.178[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:39:26.179[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:39:26.22[0m Dec 26 13:39:26.220: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-f6nqr] to have phase Bound Dec 26 13:39:26.260: INFO: PersistentVolumeClaim pvc-f6nqr found and phase=Bound (39.280749ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:39:26.26[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:39:26.296[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:39:26.333[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:39:26.333[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:39:26.374[0m Dec 26 13:39:26.374: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qvjm6" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:39:26.411: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Pending", Reason="", readiness=false. Elapsed: 36.3156ms Dec 26 13:39:28.449: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074681666s Dec 26 13:39:30.447: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.072819182s Dec 26 13:39:32.448: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Running", Reason="", readiness=true. Elapsed: 6.073735479s Dec 26 13:39:34.460: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Running", Reason="", readiness=true. Elapsed: 8.085250303s Dec 26 13:39:36.449: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Running", Reason="", readiness=false. Elapsed: 10.07424592s Dec 26 13:39:38.449: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.074846146s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:39:38.449[0m Dec 26 13:39:38.449: INFO: Pod "azurefile-volume-tester-qvjm6" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:39:38.449[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:39:38.45[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:39:38.488[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:39:38.489[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:39:38.527[0m Dec 26 13:39:38.527: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-g76ch] to have phase Bound Dec 26 13:39:38.573: INFO: PersistentVolumeClaim pvc-g76ch found but phase is Pending instead of Bound. Dec 26 13:39:40.613: INFO: PersistentVolumeClaim pvc-g76ch found and phase=Bound (2.086605895s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:39:40.614[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:39:40.65[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:39:40.686[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:39:40.687[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:39:40.726[0m Dec 26 13:39:40.727: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-h5c7m" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:39:40.764: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Pending", Reason="", readiness=false. Elapsed: 37.480374ms Dec 26 13:39:42.802: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.075091414s Dec 26 13:39:44.810: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08305045s Dec 26 13:39:46.805: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Running", Reason="", readiness=true. Elapsed: 6.078570676s Dec 26 13:39:48.802: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Running", Reason="", readiness=true. Elapsed: 8.07504502s Dec 26 13:39:50.802: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Running", Reason="", readiness=false. Elapsed: 10.074875836s Dec 26 13:39:52.806: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.0789173s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:39:52.806[0m Dec 26 13:39:52.806: INFO: Pod "azurefile-volume-tester-h5c7m" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:39:52.806[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:39:52.806[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:39:52.844[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:39:52.845[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:39:52.883[0m Dec 26 13:39:52.883: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6c6zw] to have phase Bound Dec 26 13:39:52.923: INFO: PersistentVolumeClaim pvc-6c6zw found but phase is Pending instead of Bound. Dec 26 13:39:54.961: INFO: PersistentVolumeClaim pvc-6c6zw found and phase=Bound (2.078334056s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:39:54.961[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:39:54.997[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:39:55.045[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:39:55.045[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:39:55.085[0m Dec 26 13:39:55.085: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7rc7d" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:39:55.122: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Pending", Reason="", readiness=false. Elapsed: 36.621223ms Dec 26 13:39:57.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074072856s Dec 26 13:39:59.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074960658s Dec 26 13:40:01.168: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Running", Reason="", readiness=true. Elapsed: 6.082611857s Dec 26 13:40:03.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Running", Reason="", readiness=true. Elapsed: 8.074537823s Dec 26 13:40:05.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Running", Reason="", readiness=false. Elapsed: 10.074740833s Dec 26 13:40:07.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.074547852s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:07.16[0m Dec 26 13:40:07.160: INFO: Pod "azurefile-volume-tester-7rc7d" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:40:07.16[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:40:07.16[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:40:07.207[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:40:07.207[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:40:07.25[0m Dec 26 13:40:07.250: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-cwrdw] to have phase Bound Dec 26 13:40:07.311: INFO: PersistentVolumeClaim pvc-cwrdw found and phase=Bound (60.893841ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:07.311[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:07.348[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:07.384[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:07.384[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:07.424[0m Dec 26 13:40:07.424: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-5v9mx" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:40:07.461: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Pending", Reason="", readiness=false. Elapsed: 36.156315ms Dec 26 13:40:09.499: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074920684s Dec 26 13:40:11.499: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074107325s Dec 26 13:40:13.501: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Running", Reason="", readiness=true. Elapsed: 6.076264551s Dec 26 13:40:15.498: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Running", Reason="", readiness=true. Elapsed: 8.073877519s Dec 26 13:40:17.499: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Running", Reason="", readiness=false. Elapsed: 10.074862662s Dec 26 13:40:19.501: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.076348678s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:19.501[0m Dec 26 13:40:19.501: INFO: Pod "azurefile-volume-tester-5v9mx" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:40:19.501[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:40:19.501[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:40:19.541[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:40:19.541[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:40:19.578[0m Dec 26 13:40:19.578: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6b4th] to have phase Bound Dec 26 13:40:19.615: INFO: PersistentVolumeClaim pvc-6b4th found and phase=Bound (36.529101ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:19.615[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:19.651[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:19.713[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:19.713[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:19.755[0m Dec 26 13:40:19.755: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-6422p" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:40:19.795: INFO: Pod "azurefile-volume-tester-6422p": Phase="Pending", Reason="", readiness=false. Elapsed: 39.437443ms Dec 26 13:40:21.833: INFO: Pod "azurefile-volume-tester-6422p": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0778972s Dec 26 13:40:23.833: INFO: Pod "azurefile-volume-tester-6422p": Phase="Pending", Reason="", readiness=false. Elapsed: 4.077529533s Dec 26 13:40:25.839: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=true. Elapsed: 6.083876131s Dec 26 13:40:27.832: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=true. Elapsed: 8.076975103s Dec 26 13:40:29.831: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=false. Elapsed: 10.075913692s Dec 26 13:40:31.832: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=false. Elapsed: 12.076636499s Dec 26 13:40:33.833: INFO: Pod "azurefile-volume-tester-6422p": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.077787644s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:33.833[0m Dec 26 13:40:33.834: INFO: Pod "azurefile-volume-tester-6422p" satisfied condition "Succeeded or Failed" Dec 26 13:40:33.834: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-6422p" Dec 26 13:40:33.903: INFO: Pod azurefile-volume-tester-6422p has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-6422p in namespace azurefile-2540 [38;5;243m12/26/22 13:40:33.903[0m Dec 26 13:40:33.957: INFO: deleting PVC "azurefile-2540"/"pvc-6b4th" Dec 26 13:40:33.957: INFO: Deleting PersistentVolumeClaim "pvc-6b4th" ... skipping 94 lines ... Dec 26 13:38:55.913: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-b8r6h] to have phase Bound Dec 26 13:38:55.950: INFO: PersistentVolumeClaim pvc-b8r6h found and phase=Bound (36.651631ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:38:55.95[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:38:55.988[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:38:56.025[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:38:56.025[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:38:56.064[0m Dec 26 13:38:56.064: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-2vg56" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:38:56.101: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 36.687846ms Dec 26 13:38:58.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074561167s Dec 26 13:39:00.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075499206s Dec 26 13:39:02.141: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 6.07676769s Dec 26 13:39:04.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 8.074900799s Dec 26 13:39:06.141: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Pending", Reason="", readiness=false. Elapsed: 10.076525323s ... skipping 5 lines ... Dec 26 13:39:18.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=true. Elapsed: 22.076120981s Dec 26 13:39:20.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=true. Elapsed: 24.076112814s Dec 26 13:39:22.140: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=true. Elapsed: 26.075475243s Dec 26 13:39:24.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Running", Reason="", readiness=false. Elapsed: 28.075296504s Dec 26 13:39:26.139: INFO: Pod "azurefile-volume-tester-2vg56": Phase="Succeeded", Reason="", readiness=false. Elapsed: 30.074466953s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:39:26.139[0m Dec 26 13:39:26.139: INFO: Pod "azurefile-volume-tester-2vg56" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:39:26.139[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:39:26.139[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:39:26.178[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:39:26.179[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:39:26.22[0m Dec 26 13:39:26.220: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-f6nqr] to have phase Bound Dec 26 13:39:26.260: INFO: PersistentVolumeClaim pvc-f6nqr found and phase=Bound (39.280749ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:39:26.26[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:39:26.296[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:39:26.333[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:39:26.333[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:39:26.374[0m Dec 26 13:39:26.374: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qvjm6" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:39:26.411: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Pending", Reason="", readiness=false. Elapsed: 36.3156ms Dec 26 13:39:28.449: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074681666s Dec 26 13:39:30.447: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.072819182s Dec 26 13:39:32.448: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Running", Reason="", readiness=true. Elapsed: 6.073735479s Dec 26 13:39:34.460: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Running", Reason="", readiness=true. Elapsed: 8.085250303s Dec 26 13:39:36.449: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Running", Reason="", readiness=false. Elapsed: 10.07424592s Dec 26 13:39:38.449: INFO: Pod "azurefile-volume-tester-qvjm6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.074846146s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:39:38.449[0m Dec 26 13:39:38.449: INFO: Pod "azurefile-volume-tester-qvjm6" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:39:38.449[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:39:38.45[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:39:38.488[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:39:38.489[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:39:38.527[0m Dec 26 13:39:38.527: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-g76ch] to have phase Bound Dec 26 13:39:38.573: INFO: PersistentVolumeClaim pvc-g76ch found but phase is Pending instead of Bound. Dec 26 13:39:40.613: INFO: PersistentVolumeClaim pvc-g76ch found and phase=Bound (2.086605895s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:39:40.614[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:39:40.65[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:39:40.686[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:39:40.687[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:39:40.726[0m Dec 26 13:39:40.727: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-h5c7m" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:39:40.764: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Pending", Reason="", readiness=false. Elapsed: 37.480374ms Dec 26 13:39:42.802: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.075091414s Dec 26 13:39:44.810: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08305045s Dec 26 13:39:46.805: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Running", Reason="", readiness=true. Elapsed: 6.078570676s Dec 26 13:39:48.802: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Running", Reason="", readiness=true. Elapsed: 8.07504502s Dec 26 13:39:50.802: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Running", Reason="", readiness=false. Elapsed: 10.074875836s Dec 26 13:39:52.806: INFO: Pod "azurefile-volume-tester-h5c7m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.0789173s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:39:52.806[0m Dec 26 13:39:52.806: INFO: Pod "azurefile-volume-tester-h5c7m" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:39:52.806[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:39:52.806[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:39:52.844[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:39:52.845[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:39:52.883[0m Dec 26 13:39:52.883: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6c6zw] to have phase Bound Dec 26 13:39:52.923: INFO: PersistentVolumeClaim pvc-6c6zw found but phase is Pending instead of Bound. Dec 26 13:39:54.961: INFO: PersistentVolumeClaim pvc-6c6zw found and phase=Bound (2.078334056s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:39:54.961[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:39:54.997[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:39:55.045[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:39:55.045[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:39:55.085[0m Dec 26 13:39:55.085: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7rc7d" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:39:55.122: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Pending", Reason="", readiness=false. Elapsed: 36.621223ms Dec 26 13:39:57.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074072856s Dec 26 13:39:59.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074960658s Dec 26 13:40:01.168: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Running", Reason="", readiness=true. Elapsed: 6.082611857s Dec 26 13:40:03.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Running", Reason="", readiness=true. Elapsed: 8.074537823s Dec 26 13:40:05.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Running", Reason="", readiness=false. Elapsed: 10.074740833s Dec 26 13:40:07.160: INFO: Pod "azurefile-volume-tester-7rc7d": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.074547852s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:07.16[0m Dec 26 13:40:07.160: INFO: Pod "azurefile-volume-tester-7rc7d" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:40:07.16[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:40:07.16[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:40:07.207[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:40:07.207[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:40:07.25[0m Dec 26 13:40:07.250: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-cwrdw] to have phase Bound Dec 26 13:40:07.311: INFO: PersistentVolumeClaim pvc-cwrdw found and phase=Bound (60.893841ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:07.311[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:07.348[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:07.384[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:07.384[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:07.424[0m Dec 26 13:40:07.424: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-5v9mx" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:40:07.461: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Pending", Reason="", readiness=false. Elapsed: 36.156315ms Dec 26 13:40:09.499: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074920684s Dec 26 13:40:11.499: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074107325s Dec 26 13:40:13.501: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Running", Reason="", readiness=true. Elapsed: 6.076264551s Dec 26 13:40:15.498: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Running", Reason="", readiness=true. Elapsed: 8.073877519s Dec 26 13:40:17.499: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Running", Reason="", readiness=false. Elapsed: 10.074862662s Dec 26 13:40:19.501: INFO: Pod "azurefile-volume-tester-5v9mx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.076348678s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:19.501[0m Dec 26 13:40:19.501: INFO: Pod "azurefile-volume-tester-5v9mx" satisfied condition "Succeeded or Failed" [1mSTEP:[0m setting up the PV [38;5;243m12/26/22 13:40:19.501[0m [1mSTEP:[0m creating a PV [38;5;243m12/26/22 13:40:19.501[0m [1mSTEP:[0m setting up the PVC [38;5;243m12/26/22 13:40:19.541[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:40:19.541[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:40:19.578[0m Dec 26 13:40:19.578: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6b4th] to have phase Bound Dec 26 13:40:19.615: INFO: PersistentVolumeClaim pvc-6b4th found and phase=Bound (36.529101ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:19.615[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:19.651[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:19.713[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:19.713[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:19.755[0m Dec 26 13:40:19.755: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-6422p" in namespace "azurefile-2540" to be "Succeeded or Failed" Dec 26 13:40:19.795: INFO: Pod "azurefile-volume-tester-6422p": Phase="Pending", Reason="", readiness=false. Elapsed: 39.437443ms Dec 26 13:40:21.833: INFO: Pod "azurefile-volume-tester-6422p": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0778972s Dec 26 13:40:23.833: INFO: Pod "azurefile-volume-tester-6422p": Phase="Pending", Reason="", readiness=false. Elapsed: 4.077529533s Dec 26 13:40:25.839: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=true. Elapsed: 6.083876131s Dec 26 13:40:27.832: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=true. Elapsed: 8.076975103s Dec 26 13:40:29.831: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=false. Elapsed: 10.075913692s Dec 26 13:40:31.832: INFO: Pod "azurefile-volume-tester-6422p": Phase="Running", Reason="", readiness=false. Elapsed: 12.076636499s Dec 26 13:40:33.833: INFO: Pod "azurefile-volume-tester-6422p": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.077787644s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:33.833[0m Dec 26 13:40:33.834: INFO: Pod "azurefile-volume-tester-6422p" satisfied condition "Succeeded or Failed" Dec 26 13:40:33.834: INFO: deleting Pod "azurefile-2540"/"azurefile-volume-tester-6422p" Dec 26 13:40:33.903: INFO: Pod azurefile-volume-tester-6422p has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-6422p in namespace azurefile-2540 [38;5;243m12/26/22 13:40:33.903[0m Dec 26 13:40:33.957: INFO: deleting PVC "azurefile-2540"/"pvc-6b4th" Dec 26 13:40:33.957: INFO: Deleting PersistentVolumeClaim "pvc-6b4th" ... skipping 174 lines ... Dec 26 13:40:40.121: INFO: PersistentVolumeClaim pvc-89mdc found but phase is Pending instead of Bound. Dec 26 13:40:42.161: INFO: PersistentVolumeClaim pvc-89mdc found and phase=Bound (2.096742344s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:42.161[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:42.2[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:42.238[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:42.239[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:42.285[0m Dec 26 13:40:42.285: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-xq7mk" in namespace "azurefile-5466" to be "Succeeded or Failed" Dec 26 13:40:42.347: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Pending", Reason="", readiness=false. Elapsed: 62.118082ms Dec 26 13:40:44.385: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.100184909s Dec 26 13:40:46.387: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.101735515s Dec 26 13:40:48.384: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Running", Reason="", readiness=true. Elapsed: 6.099185209s Dec 26 13:40:50.386: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Running", Reason="", readiness=true. Elapsed: 8.100937817s Dec 26 13:40:52.385: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Running", Reason="", readiness=true. Elapsed: 10.099570507s Dec 26 13:40:54.391: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.106092558s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:54.391[0m Dec 26 13:40:54.392: INFO: Pod "azurefile-volume-tester-xq7mk" satisfied condition "Succeeded or Failed" Dec 26 13:40:54.392: INFO: deleting Pod "azurefile-5466"/"azurefile-volume-tester-xq7mk" Dec 26 13:40:54.433: INFO: Pod azurefile-volume-tester-xq7mk has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-xq7mk in namespace azurefile-5466 [38;5;243m12/26/22 13:40:54.433[0m Dec 26 13:40:54.481: INFO: deleting PVC "azurefile-5466"/"pvc-89mdc" Dec 26 13:40:54.481: INFO: Deleting PersistentVolumeClaim "pvc-89mdc" ... skipping 27 lines ... Dec 26 13:40:40.121: INFO: PersistentVolumeClaim pvc-89mdc found but phase is Pending instead of Bound. Dec 26 13:40:42.161: INFO: PersistentVolumeClaim pvc-89mdc found and phase=Bound (2.096742344s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:42.161[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:42.2[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:42.238[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:42.239[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:42.285[0m Dec 26 13:40:42.285: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-xq7mk" in namespace "azurefile-5466" to be "Succeeded or Failed" Dec 26 13:40:42.347: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Pending", Reason="", readiness=false. Elapsed: 62.118082ms Dec 26 13:40:44.385: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.100184909s Dec 26 13:40:46.387: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.101735515s Dec 26 13:40:48.384: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Running", Reason="", readiness=true. Elapsed: 6.099185209s Dec 26 13:40:50.386: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Running", Reason="", readiness=true. Elapsed: 8.100937817s Dec 26 13:40:52.385: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Running", Reason="", readiness=true. Elapsed: 10.099570507s Dec 26 13:40:54.391: INFO: Pod "azurefile-volume-tester-xq7mk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.106092558s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:40:54.391[0m Dec 26 13:40:54.392: INFO: Pod "azurefile-volume-tester-xq7mk" satisfied condition "Succeeded or Failed" Dec 26 13:40:54.392: INFO: deleting Pod "azurefile-5466"/"azurefile-volume-tester-xq7mk" Dec 26 13:40:54.433: INFO: Pod azurefile-volume-tester-xq7mk has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-xq7mk in namespace azurefile-5466 [38;5;243m12/26/22 13:40:54.433[0m Dec 26 13:40:54.481: INFO: deleting PVC "azurefile-5466"/"pvc-89mdc" Dec 26 13:40:54.481: INFO: Deleting PersistentVolumeClaim "pvc-89mdc" ... skipping 27 lines ... Dec 26 13:40:56.369: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jqpks] to have phase Bound Dec 26 13:40:56.405: INFO: PersistentVolumeClaim pvc-jqpks found and phase=Bound (35.97408ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:56.405[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:56.441[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:56.492[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:56.492[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:56.533[0m Dec 26 13:40:56.533: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-jxv54" in namespace "azurefile-2790" to be "Succeeded or Failed" Dec 26 13:40:56.569: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Pending", Reason="", readiness=false. Elapsed: 36.109526ms Dec 26 13:40:58.607: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Pending", Reason="", readiness=false. Elapsed: 2.073839627s Dec 26 13:41:00.606: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Pending", Reason="", readiness=false. Elapsed: 4.073399763s Dec 26 13:41:02.608: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Running", Reason="", readiness=true. Elapsed: 6.075112208s Dec 26 13:41:04.609: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Running", Reason="", readiness=true. Elapsed: 8.075884579s Dec 26 13:41:06.607: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Running", Reason="", readiness=false. Elapsed: 10.074517866s Dec 26 13:41:08.606: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.073528215s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:41:08.606[0m Dec 26 13:41:08.607: INFO: Pod "azurefile-volume-tester-jxv54" satisfied condition "Succeeded or Failed" Dec 26 13:41:08.607: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-jxv54" Dec 26 13:41:08.647: INFO: Pod azurefile-volume-tester-jxv54 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-jxv54 in namespace azurefile-2790 [38;5;243m12/26/22 13:41:08.647[0m Dec 26 13:41:08.696: INFO: deleting PVC "azurefile-2790"/"pvc-jqpks" Dec 26 13:41:08.696: INFO: Deleting PersistentVolumeClaim "pvc-jqpks" ... skipping 31 lines ... Dec 26 13:40:56.369: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-jqpks] to have phase Bound Dec 26 13:40:56.405: INFO: PersistentVolumeClaim pvc-jqpks found and phase=Bound (35.97408ms) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:40:56.405[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:40:56.441[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:40:56.492[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:40:56.492[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:40:56.533[0m Dec 26 13:40:56.533: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-jxv54" in namespace "azurefile-2790" to be "Succeeded or Failed" Dec 26 13:40:56.569: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Pending", Reason="", readiness=false. Elapsed: 36.109526ms Dec 26 13:40:58.607: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Pending", Reason="", readiness=false. Elapsed: 2.073839627s Dec 26 13:41:00.606: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Pending", Reason="", readiness=false. Elapsed: 4.073399763s Dec 26 13:41:02.608: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Running", Reason="", readiness=true. Elapsed: 6.075112208s Dec 26 13:41:04.609: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Running", Reason="", readiness=true. Elapsed: 8.075884579s Dec 26 13:41:06.607: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Running", Reason="", readiness=false. Elapsed: 10.074517866s Dec 26 13:41:08.606: INFO: Pod "azurefile-volume-tester-jxv54": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.073528215s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:41:08.606[0m Dec 26 13:41:08.607: INFO: Pod "azurefile-volume-tester-jxv54" satisfied condition "Succeeded or Failed" Dec 26 13:41:08.607: INFO: deleting Pod "azurefile-2790"/"azurefile-volume-tester-jxv54" Dec 26 13:41:08.647: INFO: Pod azurefile-volume-tester-jxv54 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-jxv54 in namespace azurefile-2790 [38;5;243m12/26/22 13:41:08.647[0m Dec 26 13:41:08.696: INFO: deleting PVC "azurefile-2790"/"pvc-jqpks" Dec 26 13:41:08.696: INFO: Deleting PersistentVolumeClaim "pvc-jqpks" ... skipping 167 lines ... Dec 26 13:43:11.087: INFO: PersistentVolumeClaim pvc-rzqcm found but phase is Pending instead of Bound. Dec 26 13:43:13.127: INFO: PersistentVolumeClaim pvc-rzqcm found and phase=Bound (1m35.841521123s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:43:13.127[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:43:13.164[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:43:13.201[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:43:13.201[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:43:13.241[0m Dec 26 13:43:13.241: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vmwk2" in namespace "azurefile-5194" to be "Succeeded or Failed" Dec 26 13:43:13.278: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 36.644978ms Dec 26 13:43:15.316: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0746241s Dec 26 13:43:17.316: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074523052s Dec 26 13:43:19.317: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 6.075360289s Dec 26 13:43:21.315: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Running", Reason="", readiness=true. Elapsed: 8.073797343s Dec 26 13:43:23.317: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Running", Reason="", readiness=false. Elapsed: 10.075876737s Dec 26 13:43:25.314: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.073099136s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:43:25.314[0m Dec 26 13:43:25.315: INFO: Pod "azurefile-volume-tester-vmwk2" satisfied condition "Succeeded or Failed" Dec 26 13:43:25.315: INFO: deleting Pod "azurefile-5194"/"azurefile-volume-tester-vmwk2" Dec 26 13:43:25.383: INFO: Pod azurefile-volume-tester-vmwk2 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-vmwk2 in namespace azurefile-5194 [38;5;243m12/26/22 13:43:25.383[0m Dec 26 13:43:25.433: INFO: deleting PVC "azurefile-5194"/"pvc-rzqcm" Dec 26 13:43:25.433: INFO: Deleting PersistentVolumeClaim "pvc-rzqcm" ... skipping 74 lines ... Dec 26 13:43:11.087: INFO: PersistentVolumeClaim pvc-rzqcm found but phase is Pending instead of Bound. Dec 26 13:43:13.127: INFO: PersistentVolumeClaim pvc-rzqcm found and phase=Bound (1m35.841521123s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:43:13.127[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:43:13.164[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:43:13.201[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:43:13.201[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:43:13.241[0m Dec 26 13:43:13.241: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vmwk2" in namespace "azurefile-5194" to be "Succeeded or Failed" Dec 26 13:43:13.278: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 36.644978ms Dec 26 13:43:15.316: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0746241s Dec 26 13:43:17.316: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074523052s Dec 26 13:43:19.317: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Pending", Reason="", readiness=false. Elapsed: 6.075360289s Dec 26 13:43:21.315: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Running", Reason="", readiness=true. Elapsed: 8.073797343s Dec 26 13:43:23.317: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Running", Reason="", readiness=false. Elapsed: 10.075876737s Dec 26 13:43:25.314: INFO: Pod "azurefile-volume-tester-vmwk2": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.073099136s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:43:25.314[0m Dec 26 13:43:25.315: INFO: Pod "azurefile-volume-tester-vmwk2" satisfied condition "Succeeded or Failed" Dec 26 13:43:25.315: INFO: deleting Pod "azurefile-5194"/"azurefile-volume-tester-vmwk2" Dec 26 13:43:25.383: INFO: Pod azurefile-volume-tester-vmwk2 has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-vmwk2 in namespace azurefile-5194 [38;5;243m12/26/22 13:43:25.383[0m Dec 26 13:43:25.433: INFO: deleting PVC "azurefile-5194"/"pvc-rzqcm" Dec 26 13:43:25.433: INFO: Deleting PersistentVolumeClaim "pvc-rzqcm" ... skipping 29 lines ... Dec 26 13:43:31.550: INFO: PersistentVolumeClaim pvc-wngfv found but phase is Pending instead of Bound. Dec 26 13:43:33.589: INFO: PersistentVolumeClaim pvc-wngfv found and phase=Bound (2.075205153s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:43:33.589[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:43:33.626[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:43:33.662[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:43:33.662[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:43:33.703[0m Dec 26 13:43:33.703: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-j6scl" in namespace "azurefile-1353" to be "Succeeded or Failed" Dec 26 13:43:33.748: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 44.419373ms Dec 26 13:43:35.786: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.082883034s Dec 26 13:43:37.786: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.082520934s Dec 26 13:43:39.787: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.083468989s Dec 26 13:43:41.788: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.08517349s Dec 26 13:43:43.788: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Running", Reason="", readiness=true. Elapsed: 10.084558838s Dec 26 13:43:45.786: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Running", Reason="", readiness=true. Elapsed: 12.082425318s Dec 26 13:43:47.788: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Running", Reason="", readiness=false. Elapsed: 14.084873192s Dec 26 13:43:49.785: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.081756959s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:43:49.785[0m Dec 26 13:43:49.785: INFO: Pod "azurefile-volume-tester-j6scl" satisfied condition "Succeeded or Failed" Dec 26 13:43:49.785: INFO: deleting Pod "azurefile-1353"/"azurefile-volume-tester-j6scl" Dec 26 13:43:49.829: INFO: Pod azurefile-volume-tester-j6scl has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-j6scl in namespace azurefile-1353 [38;5;243m12/26/22 13:43:49.829[0m Dec 26 13:43:49.879: INFO: deleting PVC "azurefile-1353"/"pvc-wngfv" Dec 26 13:43:49.879: INFO: Deleting PersistentVolumeClaim "pvc-wngfv" ... skipping 28 lines ... Dec 26 13:43:31.550: INFO: PersistentVolumeClaim pvc-wngfv found but phase is Pending instead of Bound. Dec 26 13:43:33.589: INFO: PersistentVolumeClaim pvc-wngfv found and phase=Bound (2.075205153s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:43:33.589[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:43:33.626[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:43:33.662[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:43:33.662[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:43:33.703[0m Dec 26 13:43:33.703: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-j6scl" in namespace "azurefile-1353" to be "Succeeded or Failed" Dec 26 13:43:33.748: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 44.419373ms Dec 26 13:43:35.786: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.082883034s Dec 26 13:43:37.786: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.082520934s Dec 26 13:43:39.787: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.083468989s Dec 26 13:43:41.788: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.08517349s Dec 26 13:43:43.788: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Running", Reason="", readiness=true. Elapsed: 10.084558838s Dec 26 13:43:45.786: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Running", Reason="", readiness=true. Elapsed: 12.082425318s Dec 26 13:43:47.788: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Running", Reason="", readiness=false. Elapsed: 14.084873192s Dec 26 13:43:49.785: INFO: Pod "azurefile-volume-tester-j6scl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.081756959s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:43:49.785[0m Dec 26 13:43:49.785: INFO: Pod "azurefile-volume-tester-j6scl" satisfied condition "Succeeded or Failed" Dec 26 13:43:49.785: INFO: deleting Pod "azurefile-1353"/"azurefile-volume-tester-j6scl" Dec 26 13:43:49.829: INFO: Pod azurefile-volume-tester-j6scl has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-j6scl in namespace azurefile-1353 [38;5;243m12/26/22 13:43:49.829[0m Dec 26 13:43:49.879: INFO: deleting PVC "azurefile-1353"/"pvc-wngfv" Dec 26 13:43:49.879: INFO: Deleting PersistentVolumeClaim "pvc-wngfv" ... skipping 195 lines ... Dec 26 13:44:44.404: INFO: PersistentVolumeClaim pvc-vkkd8 found but phase is Pending instead of Bound. Dec 26 13:44:46.442: INFO: PersistentVolumeClaim pvc-vkkd8 found and phase=Bound (20.422637712s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:44:46.442[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:44:46.478[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:44:46.514[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:44:46.514[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m12/26/22 13:44:46.555[0m Dec 26 13:44:46.555: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-9nd9p" in namespace "azurefile-156" to be "Error status code" Dec 26 13:44:46.592: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Pending", Reason="", readiness=false. Elapsed: 37.585422ms Dec 26 13:44:48.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074801087s Dec 26 13:44:50.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074340988s Dec 26 13:44:52.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Running", Reason="", readiness=true. Elapsed: 6.074419926s Dec 26 13:44:54.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Running", Reason="", readiness=true. Elapsed: 8.074538401s Dec 26 13:44:56.631: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Running", Reason="", readiness=false. Elapsed: 10.075897282s Dec 26 13:44:58.653: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Failed", Reason="", readiness=false. Elapsed: 12.098238346s [1mSTEP:[0m Saw pod failure [38;5;243m12/26/22 13:44:58.653[0m Dec 26 13:44:58.653: INFO: Pod "azurefile-volume-tester-9nd9p" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m12/26/22 13:44:58.653[0m Dec 26 13:44:58.695: INFO: deleting Pod "azurefile-156"/"azurefile-volume-tester-9nd9p" Dec 26 13:44:58.736: INFO: Pod azurefile-volume-tester-9nd9p 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 46 lines ... Dec 26 13:44:44.404: INFO: PersistentVolumeClaim pvc-vkkd8 found but phase is Pending instead of Bound. Dec 26 13:44:46.442: INFO: PersistentVolumeClaim pvc-vkkd8 found and phase=Bound (20.422637712s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:44:46.442[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:44:46.478[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:44:46.514[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:44:46.514[0m [1mSTEP:[0m checking that the pods command exits with an error [38;5;243m12/26/22 13:44:46.555[0m Dec 26 13:44:46.555: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-9nd9p" in namespace "azurefile-156" to be "Error status code" Dec 26 13:44:46.592: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Pending", Reason="", readiness=false. Elapsed: 37.585422ms Dec 26 13:44:48.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074801087s Dec 26 13:44:50.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074340988s Dec 26 13:44:52.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Running", Reason="", readiness=true. Elapsed: 6.074419926s Dec 26 13:44:54.629: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Running", Reason="", readiness=true. Elapsed: 8.074538401s Dec 26 13:44:56.631: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Running", Reason="", readiness=false. Elapsed: 10.075897282s Dec 26 13:44:58.653: INFO: Pod "azurefile-volume-tester-9nd9p": Phase="Failed", Reason="", readiness=false. Elapsed: 12.098238346s [1mSTEP:[0m Saw pod failure [38;5;243m12/26/22 13:44:58.653[0m Dec 26 13:44:58.653: INFO: Pod "azurefile-volume-tester-9nd9p" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m12/26/22 13:44:58.653[0m Dec 26 13:44:58.695: INFO: deleting Pod "azurefile-156"/"azurefile-volume-tester-9nd9p" Dec 26 13:44:58.736: INFO: Pod azurefile-volume-tester-9nd9p 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 329 lines ... Dec 26 13:46:10.631: INFO: PersistentVolumeClaim pvc-qzsrn found but phase is Pending instead of Bound. Dec 26 13:46:12.669: INFO: PersistentVolumeClaim pvc-qzsrn found and phase=Bound (2.072928556s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:46:12.669[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:46:12.705[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:46:12.741[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:46:12.741[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:46:12.78[0m Dec 26 13:46:12.780: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vq276" in namespace "azurefile-2546" to be "Succeeded or Failed" Dec 26 13:46:12.815: INFO: Pod "azurefile-volume-tester-vq276": Phase="Pending", Reason="", readiness=false. Elapsed: 35.471287ms Dec 26 13:46:14.854: INFO: Pod "azurefile-volume-tester-vq276": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074116185s Dec 26 13:46:16.853: INFO: Pod "azurefile-volume-tester-vq276": Phase="Pending", Reason="", readiness=false. Elapsed: 4.072990979s Dec 26 13:46:18.852: INFO: Pod "azurefile-volume-tester-vq276": Phase="Running", Reason="", readiness=true. Elapsed: 6.07178202s Dec 26 13:46:20.852: INFO: Pod "azurefile-volume-tester-vq276": Phase="Running", Reason="", readiness=true. Elapsed: 8.07254577s Dec 26 13:46:22.852: INFO: Pod "azurefile-volume-tester-vq276": Phase="Running", Reason="", readiness=false. Elapsed: 10.07229011s Dec 26 13:46:24.853: INFO: Pod "azurefile-volume-tester-vq276": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.07294446s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:46:24.853[0m Dec 26 13:46:24.853: INFO: Pod "azurefile-volume-tester-vq276" satisfied condition "Succeeded or Failed" [1mSTEP:[0m resizing the pvc [38;5;243m12/26/22 13:46:24.889[0m [1mSTEP:[0m sleep 30s waiting for resize complete [38;5;243m12/26/22 13:46:24.935[0m [1mSTEP:[0m checking the resizing result [38;5;243m12/26/22 13:46:54.935[0m [1mSTEP:[0m checking the resizing PV result [38;5;243m12/26/22 13:46:54.972[0m [1mSTEP:[0m checking the resizing azurefile result [38;5;243m12/26/22 13:46:55.009[0m 2022/12/26 13:46:55 Running in Prow, converting AZURE_CREDENTIALS to AZURE_CREDENTIAL_FILE ... skipping 35 lines ... Dec 26 13:46:10.631: INFO: PersistentVolumeClaim pvc-qzsrn found but phase is Pending instead of Bound. Dec 26 13:46:12.669: INFO: PersistentVolumeClaim pvc-qzsrn found and phase=Bound (2.072928556s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:46:12.669[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:46:12.705[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:46:12.741[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:46:12.741[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:46:12.78[0m Dec 26 13:46:12.780: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vq276" in namespace "azurefile-2546" to be "Succeeded or Failed" Dec 26 13:46:12.815: INFO: Pod "azurefile-volume-tester-vq276": Phase="Pending", Reason="", readiness=false. Elapsed: 35.471287ms Dec 26 13:46:14.854: INFO: Pod "azurefile-volume-tester-vq276": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074116185s Dec 26 13:46:16.853: INFO: Pod "azurefile-volume-tester-vq276": Phase="Pending", Reason="", readiness=false. Elapsed: 4.072990979s Dec 26 13:46:18.852: INFO: Pod "azurefile-volume-tester-vq276": Phase="Running", Reason="", readiness=true. Elapsed: 6.07178202s Dec 26 13:46:20.852: INFO: Pod "azurefile-volume-tester-vq276": Phase="Running", Reason="", readiness=true. Elapsed: 8.07254577s Dec 26 13:46:22.852: INFO: Pod "azurefile-volume-tester-vq276": Phase="Running", Reason="", readiness=false. Elapsed: 10.07229011s Dec 26 13:46:24.853: INFO: Pod "azurefile-volume-tester-vq276": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.07294446s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:46:24.853[0m Dec 26 13:46:24.853: INFO: Pod "azurefile-volume-tester-vq276" satisfied condition "Succeeded or Failed" [1mSTEP:[0m resizing the pvc [38;5;243m12/26/22 13:46:24.889[0m [1mSTEP:[0m sleep 30s waiting for resize complete [38;5;243m12/26/22 13:46:24.935[0m [1mSTEP:[0m checking the resizing result [38;5;243m12/26/22 13:46:54.935[0m [1mSTEP:[0m checking the resizing PV result [38;5;243m12/26/22 13:46:54.972[0m [1mSTEP:[0m checking the resizing azurefile result [38;5;243m12/26/22 13:46:55.009[0m Dec 26 13:46:55.521: INFO: deleting Pod "azurefile-2546"/"azurefile-volume-tester-vq276" ... skipping 361 lines ... Dec 26 13:47:17.993: INFO: PersistentVolumeClaim pvc-wp7k7 found but phase is Pending instead of Bound. Dec 26 13:47:20.033: INFO: PersistentVolumeClaim pvc-wp7k7 found and phase=Bound (2.076545223s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:47:20.033[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:47:20.07[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:47:20.107[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:47:20.107[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:47:20.148[0m Dec 26 13:47:20.148: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7ghsq" in namespace "azurefile-9183" to be "Succeeded or Failed" Dec 26 13:47:20.187: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 39.301787ms Dec 26 13:47:22.227: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07929522s Dec 26 13:47:24.226: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.078132201s Dec 26 13:47:26.228: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.079580051s Dec 26 13:47:28.225: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.077500435s Dec 26 13:47:30.225: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Running", Reason="", readiness=true. Elapsed: 10.077081975s Dec 26 13:47:32.225: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Running", Reason="", readiness=true. Elapsed: 12.076917203s Dec 26 13:47:34.227: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Running", Reason="", readiness=false. Elapsed: 14.078646838s Dec 26 13:47:36.226: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.077853857s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:47:36.226[0m Dec 26 13:47:36.226: INFO: Pod "azurefile-volume-tester-7ghsq" satisfied condition "Succeeded or Failed" Dec 26 13:47:36.226: INFO: deleting Pod "azurefile-9183"/"azurefile-volume-tester-7ghsq" Dec 26 13:47:36.303: INFO: Pod azurefile-volume-tester-7ghsq has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-7ghsq in namespace azurefile-9183 [38;5;243m12/26/22 13:47:36.303[0m Dec 26 13:47:36.363: INFO: deleting PVC "azurefile-9183"/"pvc-wp7k7" Dec 26 13:47:36.363: INFO: Deleting PersistentVolumeClaim "pvc-wp7k7" ... skipping 128 lines ... Dec 26 13:47:17.993: INFO: PersistentVolumeClaim pvc-wp7k7 found but phase is Pending instead of Bound. Dec 26 13:47:20.033: INFO: PersistentVolumeClaim pvc-wp7k7 found and phase=Bound (2.076545223s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:47:20.033[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:47:20.07[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:47:20.107[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:47:20.107[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:47:20.148[0m Dec 26 13:47:20.148: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7ghsq" in namespace "azurefile-9183" to be "Succeeded or Failed" Dec 26 13:47:20.187: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 39.301787ms Dec 26 13:47:22.227: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07929522s Dec 26 13:47:24.226: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.078132201s Dec 26 13:47:26.228: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.079580051s Dec 26 13:47:28.225: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.077500435s Dec 26 13:47:30.225: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Running", Reason="", readiness=true. Elapsed: 10.077081975s Dec 26 13:47:32.225: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Running", Reason="", readiness=true. Elapsed: 12.076917203s Dec 26 13:47:34.227: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Running", Reason="", readiness=false. Elapsed: 14.078646838s Dec 26 13:47:36.226: INFO: Pod "azurefile-volume-tester-7ghsq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.077853857s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:47:36.226[0m Dec 26 13:47:36.226: INFO: Pod "azurefile-volume-tester-7ghsq" satisfied condition "Succeeded or Failed" Dec 26 13:47:36.226: INFO: deleting Pod "azurefile-9183"/"azurefile-volume-tester-7ghsq" Dec 26 13:47:36.303: INFO: Pod azurefile-volume-tester-7ghsq has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-7ghsq in namespace azurefile-9183 [38;5;243m12/26/22 13:47:36.303[0m Dec 26 13:47:36.363: INFO: deleting PVC "azurefile-9183"/"pvc-wp7k7" Dec 26 13:47:36.363: INFO: Deleting PersistentVolumeClaim "pvc-wp7k7" ... skipping 98 lines ... check the driver pods if restarts ... ====================================================================================== 2022/12/26 13:48:09 Check successfully Dec 26 13:48:09.359: INFO: >>> kubeConfig: /root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json 2022/12/26 13:48:09 run script: test/utils/get_storage_account_secret_name.sh 2022/12/26 13:48:09 got output: azure-storage-account-f86de6806d2dc430ba714a3-secret , error: <nil> 2022/12/26 13:48:09 got storage account secret name: azure-storage-account-f86de6806d2dc430ba714a3-secret [1mSTEP:[0m setting up the StorageClass [38;5;243m12/26/22 13:48:09.67[0m [1mSTEP:[0m creating a StorageClass [38;5;243m12/26/22 13:48:09.67[0m [1mSTEP:[0m setting up the PVC and PV [38;5;243m12/26/22 13:48:09.711[0m [1mSTEP:[0m creating a PVC [38;5;243m12/26/22 13:48:09.711[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m12/26/22 13:48:09.76[0m Dec 26 13:48:09.760: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-6ckgw] to have phase Bound Dec 26 13:48:09.796: INFO: PersistentVolumeClaim pvc-6ckgw found but phase is Pending instead of Bound. Dec 26 13:48:11.834: INFO: PersistentVolumeClaim pvc-6ckgw found and phase=Bound (2.074245907s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:48:11.835[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:48:11.871[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:48:11.907[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:48:11.907[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:48:11.947[0m Dec 26 13:48:11.947: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-b9rdl" in namespace "azurefile-1968" to be "Succeeded or Failed" Dec 26 13:48:11.983: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 36.278765ms Dec 26 13:48:14.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074799265s Dec 26 13:48:16.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074424826s Dec 26 13:48:18.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.074616842s Dec 26 13:48:20.023: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Running", Reason="", readiness=true. Elapsed: 8.076192641s Dec 26 13:48:22.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Running", Reason="", readiness=true. Elapsed: 10.074182476s Dec 26 13:48:24.022: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Running", Reason="", readiness=false. Elapsed: 12.075319561s Dec 26 13:48:26.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.07434078s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:48:26.021[0m Dec 26 13:48:26.021: INFO: Pod "azurefile-volume-tester-b9rdl" satisfied condition "Succeeded or Failed" Dec 26 13:48:26.021: INFO: deleting Pod "azurefile-1968"/"azurefile-volume-tester-b9rdl" Dec 26 13:48:26.062: INFO: Pod azurefile-volume-tester-b9rdl has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-b9rdl in namespace azurefile-1968 [38;5;243m12/26/22 13:48:26.062[0m Dec 26 13:48:26.119: INFO: deleting PVC "azurefile-1968"/"pvc-6ckgw" Dec 26 13:48:26.119: INFO: Deleting PersistentVolumeClaim "pvc-6ckgw" ... skipping 28 lines ... Dec 26 13:48:09.796: INFO: PersistentVolumeClaim pvc-6ckgw found but phase is Pending instead of Bound. Dec 26 13:48:11.834: INFO: PersistentVolumeClaim pvc-6ckgw found and phase=Bound (2.074245907s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:48:11.835[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:48:11.871[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:48:11.907[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:48:11.907[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:48:11.947[0m Dec 26 13:48:11.947: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-b9rdl" in namespace "azurefile-1968" to be "Succeeded or Failed" Dec 26 13:48:11.983: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 36.278765ms Dec 26 13:48:14.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.074799265s Dec 26 13:48:16.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.074424826s Dec 26 13:48:18.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.074616842s Dec 26 13:48:20.023: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Running", Reason="", readiness=true. Elapsed: 8.076192641s Dec 26 13:48:22.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Running", Reason="", readiness=true. Elapsed: 10.074182476s Dec 26 13:48:24.022: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Running", Reason="", readiness=false. Elapsed: 12.075319561s Dec 26 13:48:26.021: INFO: Pod "azurefile-volume-tester-b9rdl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.07434078s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:48:26.021[0m Dec 26 13:48:26.021: INFO: Pod "azurefile-volume-tester-b9rdl" satisfied condition "Succeeded or Failed" Dec 26 13:48:26.021: INFO: deleting Pod "azurefile-1968"/"azurefile-volume-tester-b9rdl" Dec 26 13:48:26.062: INFO: Pod azurefile-volume-tester-b9rdl has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-b9rdl in namespace azurefile-1968 [38;5;243m12/26/22 13:48:26.062[0m Dec 26 13:48:26.119: INFO: deleting PVC "azurefile-1968"/"pvc-6ckgw" Dec 26 13:48:26.119: INFO: Deleting PersistentVolumeClaim "pvc-6ckgw" ... skipping 38 lines ... Dec 26 13:48:50.612: INFO: PersistentVolumeClaim pvc-tmcd8 found but phase is Pending instead of Bound. Dec 26 13:48:52.649: INFO: PersistentVolumeClaim pvc-tmcd8 found and phase=Bound (20.428607606s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:48:52.649[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:48:52.684[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:48:52.721[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:48:52.721[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:48:52.761[0m Dec 26 13:48:52.761: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qcxwx" in namespace "azurefile-4657" to be "Succeeded or Failed" Dec 26 13:48:52.797: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 35.982948ms Dec 26 13:48:54.835: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07412181s Dec 26 13:48:56.836: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.07470354s Dec 26 13:48:58.836: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.074580737s Dec 26 13:49:00.837: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.075582889s Dec 26 13:49:02.835: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Running", Reason="", readiness=true. Elapsed: 10.074036073s Dec 26 13:49:04.839: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Running", Reason="", readiness=true. Elapsed: 12.077437677s Dec 26 13:49:06.835: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Running", Reason="", readiness=false. Elapsed: 14.073478453s Dec 26 13:49:08.836: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.074567773s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:49:08.836[0m Dec 26 13:49:08.836: INFO: Pod "azurefile-volume-tester-qcxwx" satisfied condition "Succeeded or Failed" Dec 26 13:49:08.836: INFO: deleting Pod "azurefile-4657"/"azurefile-volume-tester-qcxwx" Dec 26 13:49:08.905: INFO: Pod azurefile-volume-tester-qcxwx has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-qcxwx in namespace azurefile-4657 [38;5;243m12/26/22 13:49:08.905[0m Dec 26 13:49:08.957: INFO: deleting PVC "azurefile-4657"/"pvc-tmcd8" Dec 26 13:49:08.957: INFO: Deleting PersistentVolumeClaim "pvc-tmcd8" ... skipping 37 lines ... Dec 26 13:48:50.612: INFO: PersistentVolumeClaim pvc-tmcd8 found but phase is Pending instead of Bound. Dec 26 13:48:52.649: INFO: PersistentVolumeClaim pvc-tmcd8 found and phase=Bound (20.428607606s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:48:52.649[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:48:52.684[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:48:52.721[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:48:52.721[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:48:52.761[0m Dec 26 13:48:52.761: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-qcxwx" in namespace "azurefile-4657" to be "Succeeded or Failed" Dec 26 13:48:52.797: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 35.982948ms Dec 26 13:48:54.835: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07412181s Dec 26 13:48:56.836: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.07470354s Dec 26 13:48:58.836: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.074580737s Dec 26 13:49:00.837: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.075582889s Dec 26 13:49:02.835: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Running", Reason="", readiness=true. Elapsed: 10.074036073s Dec 26 13:49:04.839: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Running", Reason="", readiness=true. Elapsed: 12.077437677s Dec 26 13:49:06.835: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Running", Reason="", readiness=false. Elapsed: 14.073478453s Dec 26 13:49:08.836: INFO: Pod "azurefile-volume-tester-qcxwx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.074567773s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:49:08.836[0m Dec 26 13:49:08.836: INFO: Pod "azurefile-volume-tester-qcxwx" satisfied condition "Succeeded or Failed" Dec 26 13:49:08.836: INFO: deleting Pod "azurefile-4657"/"azurefile-volume-tester-qcxwx" Dec 26 13:49:08.905: INFO: Pod azurefile-volume-tester-qcxwx has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-qcxwx in namespace azurefile-4657 [38;5;243m12/26/22 13:49:08.905[0m Dec 26 13:49:08.957: INFO: deleting PVC "azurefile-4657"/"pvc-tmcd8" Dec 26 13:49:08.957: INFO: Deleting PersistentVolumeClaim "pvc-tmcd8" ... skipping 38 lines ... Dec 26 13:49:33.350: INFO: PersistentVolumeClaim pvc-fcskv found but phase is Pending instead of Bound. Dec 26 13:49:35.388: INFO: PersistentVolumeClaim pvc-fcskv found and phase=Bound (20.420261752s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:49:35.388[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:49:35.425[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:49:35.46[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:49:35.46[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:49:35.5[0m Dec 26 13:49:35.500: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7f7qx" in namespace "azurefile-1359" to be "Succeeded or Failed" Dec 26 13:49:35.537: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 37.767012ms Dec 26 13:49:37.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07622114s Dec 26 13:49:39.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075819976s Dec 26 13:49:41.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.076491841s Dec 26 13:49:43.575: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Running", Reason="", readiness=true. Elapsed: 8.07532436s Dec 26 13:49:45.586: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Running", Reason="", readiness=true. Elapsed: 10.086550125s Dec 26 13:49:47.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Running", Reason="", readiness=false. Elapsed: 12.07635275s Dec 26 13:49:49.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.076274876s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:49:49.576[0m Dec 26 13:49:49.579: INFO: Pod "azurefile-volume-tester-7f7qx" satisfied condition "Succeeded or Failed" Dec 26 13:49:49.579: INFO: deleting Pod "azurefile-1359"/"azurefile-volume-tester-7f7qx" Dec 26 13:49:49.627: INFO: Pod azurefile-volume-tester-7f7qx has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-7f7qx in namespace azurefile-1359 [38;5;243m12/26/22 13:49:49.627[0m Dec 26 13:49:49.683: INFO: deleting PVC "azurefile-1359"/"pvc-fcskv" Dec 26 13:49:49.683: INFO: Deleting PersistentVolumeClaim "pvc-fcskv" ... skipping 37 lines ... Dec 26 13:49:33.350: INFO: PersistentVolumeClaim pvc-fcskv found but phase is Pending instead of Bound. Dec 26 13:49:35.388: INFO: PersistentVolumeClaim pvc-fcskv found and phase=Bound (20.420261752s) [1mSTEP:[0m checking the PVC [38;5;243m12/26/22 13:49:35.388[0m [1mSTEP:[0m validating provisioned PV [38;5;243m12/26/22 13:49:35.425[0m [1mSTEP:[0m checking the PV [38;5;243m12/26/22 13:49:35.46[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:49:35.46[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:49:35.5[0m Dec 26 13:49:35.500: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-7f7qx" in namespace "azurefile-1359" to be "Succeeded or Failed" Dec 26 13:49:35.537: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 37.767012ms Dec 26 13:49:37.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07622114s Dec 26 13:49:39.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075819976s Dec 26 13:49:41.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.076491841s Dec 26 13:49:43.575: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Running", Reason="", readiness=true. Elapsed: 8.07532436s Dec 26 13:49:45.586: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Running", Reason="", readiness=true. Elapsed: 10.086550125s Dec 26 13:49:47.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Running", Reason="", readiness=false. Elapsed: 12.07635275s Dec 26 13:49:49.576: INFO: Pod "azurefile-volume-tester-7f7qx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.076274876s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:49:49.576[0m Dec 26 13:49:49.579: INFO: Pod "azurefile-volume-tester-7f7qx" satisfied condition "Succeeded or Failed" Dec 26 13:49:49.579: INFO: deleting Pod "azurefile-1359"/"azurefile-volume-tester-7f7qx" Dec 26 13:49:49.627: INFO: Pod azurefile-volume-tester-7f7qx has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-7f7qx in namespace azurefile-1359 [38;5;243m12/26/22 13:49:49.627[0m Dec 26 13:49:49.683: INFO: deleting PVC "azurefile-1359"/"pvc-fcskv" Dec 26 13:49:49.683: INFO: Deleting PersistentVolumeClaim "pvc-fcskv" ... skipping 116 lines ... I1226 13:51:16.538713 15289 testsuites.go:627] 0/1 replicas in the StatefulSet are ready I1226 13:51:18.538681 15289 testsuites.go:627] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m12/26/22 13:51:18.575[0m [1mSTEP:[0m check pod exec [38;5;243m12/26/22 13:51:18.612[0m Dec 26 13:51:18.612: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com --kubeconfig=/root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json --namespace=azurefile-6200 exec azurefile-volume-tester-dbddx-0 -- cmd /c type C:\mnt\test-1\data.txt' Dec 26 13:51:19.376: INFO: rc: 1 Dec 26 13:51:19.376: INFO: Error waiting for output "hello world\r\n" in pod "azurefile-volume-tester-dbddx-0": error running /usr/local/bin/kubectl --server=https://kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com --kubeconfig=/root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json --namespace=azurefile-6200 exec azurefile-volume-tester-dbddx-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. Dec 26 13:51:21.376: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com --kubeconfig=/root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json --namespace=azurefile-6200 exec azurefile-volume-tester-dbddx-0 -- cmd /c type C:\mnt\test-1\data.txt' Dec 26 13:51:22.087: INFO: stderr: "" Dec 26 13:51:22.087: INFO: stdout: "hello world\r\n" [1mSTEP:[0m delete volume first, make sure pod could still be terminated [38;5;243m12/26/22 13:51:22.087[0m Dec 26 13:51:22.087: INFO: deleting StatefulSet "azurefile-6200"/"azurefile-volume-tester-dbddx" Dec 26 13:51:22.191: INFO: Pod azurefile-volume-tester-dbddx-0 has the following logs: Dec 26 13:51:22.246: INFO: deleting StorageClass azurefile-6200-file.csi.azure.com-dynamic-sc-k4k7b [1mSTEP:[0m dump namespace information after failure [38;5;243m12/26/22 13:51:22.306[0m [1mSTEP:[0m Destroying namespace "azurefile-6200" for this suite. [38;5;243m12/26/22 13:51:22.307[0m [38;5;243m------------------------------[0m [38;5;9m• [FAILED] [12.589 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 be able to unmount volume if volume is already deleted [file.csi.azure.com][0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning_test.go:868[0m [38;5;243mBegin Captured GinkgoWriter Output >>[0m ... skipping 14 lines ... I1226 13:51:16.538713 15289 testsuites.go:627] 0/1 replicas in the StatefulSet are ready I1226 13:51:18.538681 15289 testsuites.go:627] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m12/26/22 13:51:18.575[0m [1mSTEP:[0m check pod exec [38;5;243m12/26/22 13:51:18.612[0m Dec 26 13:51:18.612: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com --kubeconfig=/root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json --namespace=azurefile-6200 exec azurefile-volume-tester-dbddx-0 -- cmd /c type C:\mnt\test-1\data.txt' Dec 26 13:51:19.376: INFO: rc: 1 Dec 26 13:51:19.376: INFO: Error waiting for output "hello world\r\n" in pod "azurefile-volume-tester-dbddx-0": error running /usr/local/bin/kubectl --server=https://kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com --kubeconfig=/root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json --namespace=azurefile-6200 exec azurefile-volume-tester-dbddx-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. Dec 26 13:51:21.376: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com --kubeconfig=/root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json --namespace=azurefile-6200 exec azurefile-volume-tester-dbddx-0 -- cmd /c type C:\mnt\test-1\data.txt' Dec 26 13:51:22.087: INFO: stderr: "" Dec 26 13:51:22.087: INFO: stdout: "hello world\r\n" [1mSTEP:[0m delete volume first, make sure pod could still be terminated [38;5;243m12/26/22 13:51:22.087[0m Dec 26 13:51:22.087: INFO: deleting StatefulSet "azurefile-6200"/"azurefile-volume-tester-dbddx" Dec 26 13:51:22.191: INFO: Pod azurefile-volume-tester-dbddx-0 has the following logs: Dec 26 13:51:22.246: INFO: deleting StorageClass azurefile-6200-file.csi.azure.com-dynamic-sc-k4k7b [1mSTEP:[0m dump namespace information after failure [38;5;243m12/26/22 13:51:22.306[0m [1mSTEP:[0m Destroying namespace "azurefile-6200" for this suite. [38;5;243m12/26/22 13:51:22.307[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;9mUnexpected error: <*status.Error | 0xc000597160>: { s: { s: { state: { NoUnkeyedLiterals: {}, DoNotCompare: [], DoNotCopy: [], ... skipping 4 lines ... Code: 3, Message: "Volume ID missing in request", Details: nil, }, }, } rpc error: code = InvalidArgument desc = Volume ID missing in request occurred[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/dynamically_provisioned_volume_unmount_tester.go:63[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(0xc0004f81e0) /home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:271 +0x179 ... skipping 14 lines ... check the driver pods if restarts ... ====================================================================================== 2022/12/26 13:51:22 Check successfully Dec 26 13:51:22.945: INFO: >>> kubeConfig: /root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json 2022/12/26 13:51:22 run script: test/utils/get_storage_account_secret_name.sh 2022/12/26 13:51:23 got output: azure-storage-account-f86de6806d2dc430ba714a3-secret , error: <nil> 2022/12/26 13:51:23 got storage account secret name: azure-storage-account-f86de6806d2dc430ba714a3-secret [1mSTEP:[0m Successfully provisioned AzureFile volume: "kubetest-dbvgcbg1#f86de6806d2dc430ba714a3#csi-inline-smb-volume##csi-inline-smb-volume#azurefile-5399" [38;5;243m12/26/22 13:51:24.485[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:51:24.485[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:51:24.528[0m Dec 26 13:51:24.528: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-x84cc" in namespace "azurefile-5399" to be "Succeeded or Failed" Dec 26 13:51:24.564: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 36.417568ms Dec 26 13:51:26.603: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07516512s Dec 26 13:51:28.602: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.073966266s Dec 26 13:51:30.607: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.078938352s Dec 26 13:51:32.603: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Running", Reason="", readiness=true. Elapsed: 8.075115151s Dec 26 13:51:34.602: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Running", Reason="", readiness=true. Elapsed: 10.074498629s Dec 26 13:51:36.604: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Running", Reason="", readiness=false. Elapsed: 12.07588894s Dec 26 13:51:38.603: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.074958718s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:51:38.603[0m Dec 26 13:51:38.603: INFO: Pod "azurefile-volume-tester-x84cc" satisfied condition "Succeeded or Failed" Dec 26 13:51:38.603: INFO: deleting Pod "azurefile-5399"/"azurefile-volume-tester-x84cc" Dec 26 13:51:38.644: INFO: Pod azurefile-volume-tester-x84cc has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-x84cc in namespace azurefile-5399 [38;5;243m12/26/22 13:51:38.644[0m [1mSTEP:[0m Destroying namespace "azurefile-5399" for this suite. [38;5;243m12/26/22 13:51:38.69[0m [38;5;243m------------------------------[0m ... skipping 10 lines ... [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m12/26/22 13:51:22.475[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m12/26/22 13:51:22.546[0m Dec 26 13:51:22.945: INFO: >>> kubeConfig: /root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json [1mSTEP:[0m Successfully provisioned AzureFile volume: "kubetest-dbvgcbg1#f86de6806d2dc430ba714a3#csi-inline-smb-volume##csi-inline-smb-volume#azurefile-5399" [38;5;243m12/26/22 13:51:24.485[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:51:24.485[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:51:24.528[0m Dec 26 13:51:24.528: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-x84cc" in namespace "azurefile-5399" to be "Succeeded or Failed" Dec 26 13:51:24.564: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 36.417568ms Dec 26 13:51:26.603: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.07516512s Dec 26 13:51:28.602: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.073966266s Dec 26 13:51:30.607: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.078938352s Dec 26 13:51:32.603: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Running", Reason="", readiness=true. Elapsed: 8.075115151s Dec 26 13:51:34.602: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Running", Reason="", readiness=true. Elapsed: 10.074498629s Dec 26 13:51:36.604: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Running", Reason="", readiness=false. Elapsed: 12.07588894s Dec 26 13:51:38.603: INFO: Pod "azurefile-volume-tester-x84cc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.074958718s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:51:38.603[0m Dec 26 13:51:38.603: INFO: Pod "azurefile-volume-tester-x84cc" satisfied condition "Succeeded or Failed" Dec 26 13:51:38.603: INFO: deleting Pod "azurefile-5399"/"azurefile-volume-tester-x84cc" Dec 26 13:51:38.644: INFO: Pod azurefile-volume-tester-x84cc has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-x84cc in namespace azurefile-5399 [38;5;243m12/26/22 13:51:38.644[0m [1mSTEP:[0m Destroying namespace "azurefile-5399" for this suite. [38;5;243m12/26/22 13:51:38.69[0m [38;5;243m<< End Captured GinkgoWriter Output[0m ... skipping 45 lines ... ====================================================================================== 2022/12/26 13:51:40 Check successfully Dec 26 13:51:40.016: INFO: >>> kubeConfig: /root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json [1mSTEP:[0m creating secret smbcreds in namespace azurefile-8675 [38;5;243m12/26/22 13:51:40.017[0m 2022/12/26 13:51:40 run script: test/utils/get_smb_svc_public_ip.sh 2022/12/26 13:51:40 got output: 13.85.196.74 , error: <nil> 2022/12/26 13:51:40 use server on Windows: 13.85.196.74 [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:51:40.339[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:51:40.381[0m Dec 26 13:51:40.381: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4qhtd" in namespace "azurefile-8675" to be "Succeeded or Failed" Dec 26 13:51:40.423: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Pending", Reason="", readiness=false. Elapsed: 41.738353ms Dec 26 13:51:42.460: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.079242624s Dec 26 13:51:44.467: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086315935s Dec 26 13:51:46.461: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Running", Reason="", readiness=true. Elapsed: 6.079723333s Dec 26 13:51:48.462: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Running", Reason="", readiness=true. Elapsed: 8.080706619s Dec 26 13:51:50.462: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Running", Reason="", readiness=false. Elapsed: 10.081065101s Dec 26 13:51:52.460: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.079165491s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:51:52.46[0m Dec 26 13:51:52.460: INFO: Pod "azurefile-volume-tester-4qhtd" satisfied condition "Succeeded or Failed" Dec 26 13:51:52.460: INFO: deleting Pod "azurefile-8675"/"azurefile-volume-tester-4qhtd" Dec 26 13:51:52.502: INFO: Pod azurefile-volume-tester-4qhtd has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-4qhtd in namespace azurefile-8675 [38;5;243m12/26/22 13:51:52.502[0m Dec 26 13:51:52.549: INFO: deleting Secret smbcreds [1mSTEP:[0m Destroying namespace "azurefile-8675" for this suite. [38;5;243m12/26/22 13:51:52.587[0m ... skipping 10 lines ... [1mSTEP:[0m Building a namespace api object, basename azurefile [38;5;243m12/26/22 13:51:39.422[0m [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m12/26/22 13:51:39.532[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m12/26/22 13:51:39.602[0m Dec 26 13:51:40.016: INFO: >>> kubeConfig: /root/tmp3584716969/kubeconfig/kubeconfig.southcentralus.json [1mSTEP:[0m creating secret smbcreds in namespace azurefile-8675 [38;5;243m12/26/22 13:51:40.017[0m [1mSTEP:[0m deploying the pod [38;5;243m12/26/22 13:51:40.339[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m12/26/22 13:51:40.381[0m Dec 26 13:51:40.381: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-4qhtd" in namespace "azurefile-8675" to be "Succeeded or Failed" Dec 26 13:51:40.423: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Pending", Reason="", readiness=false. Elapsed: 41.738353ms Dec 26 13:51:42.460: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.079242624s Dec 26 13:51:44.467: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.086315935s Dec 26 13:51:46.461: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Running", Reason="", readiness=true. Elapsed: 6.079723333s Dec 26 13:51:48.462: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Running", Reason="", readiness=true. Elapsed: 8.080706619s Dec 26 13:51:50.462: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Running", Reason="", readiness=false. Elapsed: 10.081065101s Dec 26 13:51:52.460: INFO: Pod "azurefile-volume-tester-4qhtd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.079165491s [1mSTEP:[0m Saw pod success [38;5;243m12/26/22 13:51:52.46[0m Dec 26 13:51:52.460: INFO: Pod "azurefile-volume-tester-4qhtd" satisfied condition "Succeeded or Failed" Dec 26 13:51:52.460: INFO: deleting Pod "azurefile-8675"/"azurefile-volume-tester-4qhtd" Dec 26 13:51:52.502: INFO: Pod azurefile-volume-tester-4qhtd has the following logs: hello world [1mSTEP:[0m Deleting pod azurefile-volume-tester-4qhtd in namespace azurefile-8675 [38;5;243m12/26/22 13:51:52.502[0m Dec 26 13:51:52.549: INFO: deleting Secret smbcreds [1mSTEP:[0m Destroying namespace "azurefile-8675" for this suite. [38;5;243m12/26/22 13:51:52.587[0m ... skipping 158 lines ... Streaming logs below: I1226 13:37:41.684762 1 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test I1226 13:37:41.684931 1 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:37:41.685385 1 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:37:41.719060 1 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 33 milliseconds I1226 13:37:41.719487 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 I1226 13:37:41.719510 1 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:37:41.719521 1 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I1226 13:37:41.719561 1 azure.go:110] read cloud config from file: /etc/kubernetes/azure.json successfully I1226 13:37:41.720511 1 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:37:41.720574 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:37:41.720617 1 azure.go:775] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 ... skipping 30 lines ... I1226 13:37:41.721193 1 azure_vmasclient.go:70] Azure AvailabilitySetsClient (read ops) using rate limit config: QPS=100, bucket=1000 I1226 13:37:41.721245 1 azure_vmasclient.go:73] Azure AvailabilitySetsClient (write ops) using rate limit config: QPS=100, bucket=1000 I1226 13:37:41.721382 1 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I1226 13:37:41.721437 1 azure.go:140] disable UseInstanceMetadata for controller server I1226 13:37:41.721483 1 azure.go:143] starting controller server... I1226 13:37:41.721532 1 azurefile.go:304] cloud: AzurePublicCloud, location: southcentralus, rg: kubetest-dbvgcbg1, VnetName: k8s-vnet-24837443, VnetResourceGroup: , SubnetName: k8s-subnet I1226 13:37:41.725663 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount565357689' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount565357689: must be superuser to unmount. I1226 13:37:41.725698 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I1226 13:37:41.725842 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME I1226 13:37:41.725856 1 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I1226 13:37:41.725905 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I1226 13:37:41.725923 1 driver.go:93] Enabling controller service capability: EXPAND_VOLUME I1226 13:37:41.725929 1 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER ... skipping 515 lines ... X-Ms-Request-Id: e35f07b1-51f1-4f48-b1d7-ed3534ea15fa X-Ms-Correlation-Request-Id: e35f07b1-51f1-4f48-b1d7-ed3534ea15fa X-Content-Type-Options: nosniff Date: Mon, 26 Dec 2022 13:41:36 GMT Content-Length: 256 I1226 13:41:37.404716 1 util.go:124] Send.sendRequest got response with ContentLength 256, StatusCode 404 and responseBody length 256 I1226 13:41:37.404733 1 azure_privatednsclient.go:215] Received error in privatednszone.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/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 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:41:37.404883 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.02387755 request="private_dns_zones_get" resource_group="kubetest-dbvgcbg1" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I1226 13:41:37.404905 1 azure_storageaccount.go:210] 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 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:41:37.404914 1 azure_storageaccount.go:423] Creating private dns zone(privatelink.file.core.windows.net) in resourceGroup (kubetest-dbvgcbg1) (2022-12-26T13:41:37.4049752Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 Content-Type: application/json; charset=utf-8 User-Agent: Go/go1.19.4 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test Authorization: **REDACTED** (2022-12-26T13:41:37.4050255Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 ... skipping 140 lines ... X-Ms-Correlation-Request-Id: 84c8d81d-1a2d-4287-b5e5-6a7777b53c98 X-Ms-Routing-Request-Id: SOUTHCENTRALUS:20221226T134208Z:84c8d81d-1a2d-4287-b5e5-6a7777b53c98 Strict-Transport-Security: max-age=31536000; includeSubDomains Date: Mon, 26 Dec 2022 13:42:08 GMT Content-Length: 309 I1226 13:42:08.983858 1 util.go:124] Send.sendRequest got response with ContentLength 309, StatusCode 404 and responseBody length 309 I1226 13:42:08.983960 1 azure_virtualnetworklinksclient.go:212] Received error in virtualnetworklink.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink, error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink' under resource group 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:42:08.984190 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.098774054 request="virtual_network_links_get" resource_group="kubetest-dbvgcbg1" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I1226 13:42:08.984237 1 azure_storageaccount.go:220] get virtual link for vnet(k8s-vnet-24837443) 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/f236f77495ba142adb8b72d-vnetlink' under resource group 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:42:08.984249 1 azure_storageaccount.go:438] Creating virtual link for vnet(f236f77495ba142adb8b72d-vnetlink) and DNS Zone(privatelink.file.core.windows.net) in resourceGroup(kubetest-dbvgcbg1) (2022-12-26T13:42:08.9844122Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink?api-version=2020-06-01 Content-Type: application/json; charset=utf-8 User-Agent: Go/go1.19.4 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test Authorization: **REDACTED** (2022-12-26T13:42:08.9846481Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink?api-version=2020-06-01 ... skipping 3421 lines ... Streaming logs below: I1226 13:37:59.326654 6948 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test I1226 13:37:59.345552 6948 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:37:59.350550 6948 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:37:59.398306 6948 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 45 milliseconds I1226 13:37:59.399664 6948 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 I1226 13:37:59.399664 6948 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:37:59.399664 6948 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I1226 13:37:59.407154 6948 azure.go:110] read cloud config from file: C:\k\azure.json successfully I1226 13:37:59.409822 6948 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:37:59.410465 6948 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:37:59.411779 6948 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 40 lines ... I1226 13:38:56.346976 6948 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities I1226 13:38:56.346976 6948 utils.go:77] GRPC request: {} I1226 13:38:56.346976 6948 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]} I1226 13:38:56.349579 6948 utils.go:76] GRPC call: /csi.v1.Node/NodeStageVolume I1226 13:38:56.349579 6948 utils.go:77] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\pv\\azurefile-2540-file.csi.azure.com-preprovsioned-pv-nqpdp\\globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_id":"kubetest-dbvgcbg1#f86de6806d2dc430ba714a3#pre-provisioned-multiple-pods##pre-provisioned-multiple-pods#azurefile-25401"} I1226 13:38:56.355829 6948 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/azurefile-25401/secrets/azure-storage-account-f86de6806d2dc430ba714a3-secret 404 Not Found in 5 milliseconds W1226 13:38:56.355829 6948 azurefile.go:668] GetStorageAccountFromSecret(azure-storage-account-f86de6806d2dc430ba714a3-secret, azurefile-25401) failed with error: could not get secret(azure-storage-account-f86de6806d2dc430ba714a3-secret): secrets "azure-storage-account-f86de6806d2dc430ba714a3-secret" not found I1226 13:38:56.355829 6948 azurefile.go:670] use cluster identity to get account key from (0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e, kubetest-dbvgcbg1, f86de6806d2dc430ba714a3) (2022-12-26T13:38:56.3564437Z) INFO: REQUEST: POST https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token User-Agent: Go/go1.19.4 (amd64-windows) go-autorest/adal/v1.0.0 Content-Type: application/x-www-form-urlencoded (2022-12-26T13:38:56.9681180Z) INFO: RESPONSE: 200 https://login.microsoftonline.com/097f89a0-9286-43d2-9a1a-08f1d49b1af8/oauth2/token Pragma: no-cache ... skipping 1249 lines ... I1226 13:51:40.682668 6948 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities I1226 13:51:40.682668 6948 utils.go:77] GRPC request: {} I1226 13:51:40.682745 6948 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]} I1226 13:51:40.684243 6948 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume I1226 13:51:40.684337 6948 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\ee5372cf-100b-497f-90f5-32626e71fe7e\\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-4qhtd","csi.storage.k8s.io/pod.namespace":"azurefile-8675","csi.storage.k8s.io/pod.uid":"ee5372cf-100b-497f-90f5-32626e71fe7e","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"dir_mode=0755,file_mode=0721,cache=singleclient","secretName":"smbcreds","server":"13.85.196.74","shareName":"share"},"volume_id":"csi-7b3e9f75fe96e7cadae0325880923b7743c3ede3237fc473e6fcf6e8ac64d3c9"} I1226 13:51:40.684400 6948 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-7b3e9f75fe96e7cadae0325880923b7743c3ede3237fc473e6fcf6e8ac64d3c9) mount on c:\var\lib\kubelet\pods\ee5372cf-100b-497f-90f5-32626e71fe7e\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-4qhtd csi.storage.k8s.io/pod.namespace:azurefile-8675 csi.storage.k8s.io/pod.uid:ee5372cf-100b-497f-90f5-32626e71fe7e csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:dir_mode=0755,file_mode=0721,cache=singleclient secretName:smbcreds secretnamespace:azurefile-8675 server:13.85.196.74 shareName:share storageaccount:] W1226 13:51:40.684400 6948 azurefile.go:595] parsing volumeID(csi-7b3e9f75fe96e7cadae0325880923b7743c3ede3237fc473e6fcf6e8ac64d3c9) return with error: error parsing volume id: "csi-7b3e9f75fe96e7cadae0325880923b7743c3ede3237fc473e6fcf6e8ac64d3c9", should at least contain two # I1226 13:51:40.732207 6948 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/azurefile-8675/secrets/smbcreds 200 OK in 38 milliseconds I1226 13:51:40.733121 6948 nodeserver.go:302] cifsMountPath(c:\var\lib\kubelet\pods\ee5372cf-100b-497f-90f5-32626e71fe7e\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-7b3e9f75fe96e7cadae0325880923b7743c3ede3237fc473e6fcf6e8ac64d3c9) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-4qhtd csi.storage.k8s.io/pod.namespace:azurefile-8675 csi.storage.k8s.io/pod.uid:ee5372cf-100b-497f-90f5-32626e71fe7e csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:dir_mode=0755,file_mode=0721,cache=singleclient secretName:smbcreds secretnamespace:azurefile-8675 server:13.85.196.74 shareName:share storageaccount:]) mountflags([]) mountOptions([AZURE\USERNAME]) volumeMountGroup() I1226 13:51:40.733210 6948 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\ee5372cf-100b-497f-90f5-32626e71fe7e\volumes\kubernetes.io~csi\test-volume-1\mount I1226 13:51:40.733210 6948 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\ee5372cf-100b-497f-90f5-32626e71fe7e\volumes\kubernetes.io~csi\test-volume-1\mount I1226 13:51:40.734861 6948 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\ee5372cf-100b-497f-90f5-32626e71fe7e\volumes\kubernetes.io~csi\test-volume-1\mount I1226 13:51:40.734935 6948 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\ee5372cf-100b-497f-90f5-32626e71fe7e\volumes\kubernetes.io~csi\test-volume-1\mount ... skipping 29 lines ... Streaming logs below: I1226 13:37:57.619909 6544 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test I1226 13:37:57.632927 6544 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:37:57.653778 6544 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:37:57.697379 6544 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 42 milliseconds I1226 13:37:57.698593 6544 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 I1226 13:37:57.698593 6544 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:37:57.698593 6544 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I1226 13:37:57.705968 6544 azure.go:110] read cloud config from file: C:\k\azure.json successfully I1226 13:37:57.716649 6544 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:37:57.716809 6544 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:37:57.718373 6544 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 828 lines ... I1226 13:51:24.760554 6544 utils.go:76] GRPC call: /csi.v1.Node/NodeGetCapabilities I1226 13:51:24.760606 6544 utils.go:77] GRPC request: {} I1226 13:51:24.760743 6544 utils.go:83] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":2}}}]} I1226 13:51:24.761948 6544 utils.go:76] GRPC call: /csi.v1.Node/NodePublishVolume I1226 13:51:24.761948 6544 utils.go:77] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\c259d789-134e-42ec-b923-92298b2a91e9\\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-x84cc","csi.storage.k8s.io/pod.namespace":"azurefile-5399","csi.storage.k8s.io/pod.uid":"c259d789-134e-42ec-b923-92298b2a91e9","csi.storage.k8s.io/serviceAccount.name":"default","mountOptions":"dir_mode=0755,file_mode=0721,cache=singleclient","secretName":"azure-storage-account-f86de6806d2dc430ba714a3-secret","server":"","shareName":"csi-inline-smb-volume"},"volume_id":"csi-44629d9e4d1feea40733c37183f0ef9328a9299d969f5a6f246751a85d82cace"} I1226 13:51:24.761948 6544 nodeserver.go:68] NodePublishVolume: ephemeral volume(csi-44629d9e4d1feea40733c37183f0ef9328a9299d969f5a6f246751a85d82cace) mount on c:\var\lib\kubelet\pods\c259d789-134e-42ec-b923-92298b2a91e9\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-x84cc csi.storage.k8s.io/pod.namespace:azurefile-5399 csi.storage.k8s.io/pod.uid:c259d789-134e-42ec-b923-92298b2a91e9 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:dir_mode=0755,file_mode=0721,cache=singleclient secretName:azure-storage-account-f86de6806d2dc430ba714a3-secret secretnamespace:azurefile-5399 server: shareName:csi-inline-smb-volume storageaccount:] W1226 13:51:24.761948 6544 azurefile.go:595] parsing volumeID(csi-44629d9e4d1feea40733c37183f0ef9328a9299d969f5a6f246751a85d82cace) return with error: error parsing volume id: "csi-44629d9e4d1feea40733c37183f0ef9328a9299d969f5a6f246751a85d82cace", should at least contain two # I1226 13:51:24.800592 6544 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/azurefile-5399/secrets/azure-storage-account-f86de6806d2dc430ba714a3-secret 200 OK in 37 milliseconds I1226 13:51:24.800626 6544 nodeserver.go:302] cifsMountPath(c:\var\lib\kubelet\pods\c259d789-134e-42ec-b923-92298b2a91e9\volumes\kubernetes.io~csi\test-volume-1\mount) fstype() volumeID(csi-44629d9e4d1feea40733c37183f0ef9328a9299d969f5a6f246751a85d82cace) context(map[csi.storage.k8s.io/ephemeral:true csi.storage.k8s.io/pod.name:azurefile-volume-tester-x84cc csi.storage.k8s.io/pod.namespace:azurefile-5399 csi.storage.k8s.io/pod.uid:c259d789-134e-42ec-b923-92298b2a91e9 csi.storage.k8s.io/serviceAccount.name:default getaccountkeyfromsecret:true mountOptions:dir_mode=0755,file_mode=0721,cache=singleclient secretName:azure-storage-account-f86de6806d2dc430ba714a3-secret secretnamespace:azurefile-5399 server: shareName:csi-inline-smb-volume storageaccount:]) mountflags([]) mountOptions([AZURE\f86de6806d2dc430ba714a3]) volumeMountGroup() I1226 13:51:24.800626 6544 safe_mounter_windows.go:163] IsLikelyNotMountPoint: c:\var\lib\kubelet\pods\c259d789-134e-42ec-b923-92298b2a91e9\volumes\kubernetes.io~csi\test-volume-1\mount I1226 13:51:24.800626 6544 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\c259d789-134e-42ec-b923-92298b2a91e9\volumes\kubernetes.io~csi\test-volume-1\mount I1226 13:51:24.802019 6544 safe_mounter_windows.go:220] Exists path: c:\var\lib\kubelet\pods\c259d789-134e-42ec-b923-92298b2a91e9\volumes\kubernetes.io~csi\test-volume-1\mount I1226 13:51:24.802786 6544 azure_common_windows.go:73] Removing path: c:\var\lib\kubelet\pods\c259d789-134e-42ec-b923-92298b2a91e9\volumes\kubernetes.io~csi\test-volume-1\mount ... skipping 434 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 48709 # 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 17153 # 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 386 lines ... Streaming logs below: I1226 13:37:41.684762 1 azurefile.go:299] driver userAgent: file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test I1226 13:37:41.684931 1 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:37:41.685385 1 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:37:41.719060 1 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 33 milliseconds I1226 13:37:41.719487 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 I1226 13:37:41.719510 1 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:37:41.719521 1 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I1226 13:37:41.719561 1 azure.go:110] read cloud config from file: /etc/kubernetes/azure.json successfully I1226 13:37:41.720511 1 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:37:41.720574 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:37:41.720617 1 azure.go:775] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 ... skipping 30 lines ... I1226 13:37:41.721193 1 azure_vmasclient.go:70] Azure AvailabilitySetsClient (read ops) using rate limit config: QPS=100, bucket=1000 I1226 13:37:41.721245 1 azure_vmasclient.go:73] Azure AvailabilitySetsClient (write ops) using rate limit config: QPS=100, bucket=1000 I1226 13:37:41.721382 1 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I1226 13:37:41.721437 1 azure.go:140] disable UseInstanceMetadata for controller server I1226 13:37:41.721483 1 azure.go:143] starting controller server... I1226 13:37:41.721532 1 azurefile.go:304] cloud: AzurePublicCloud, location: southcentralus, rg: kubetest-dbvgcbg1, VnetName: k8s-vnet-24837443, VnetResourceGroup: , SubnetName: k8s-subnet I1226 13:37:41.725663 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount565357689' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount565357689: must be superuser to unmount. I1226 13:37:41.725698 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I1226 13:37:41.725842 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME I1226 13:37:41.725856 1 driver.go:93] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I1226 13:37:41.725905 1 driver.go:93] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I1226 13:37:41.725923 1 driver.go:93] Enabling controller service capability: EXPAND_VOLUME I1226 13:37:41.725929 1 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER ... skipping 515 lines ... X-Ms-Request-Id: e35f07b1-51f1-4f48-b1d7-ed3534ea15fa X-Ms-Correlation-Request-Id: e35f07b1-51f1-4f48-b1d7-ed3534ea15fa X-Content-Type-Options: nosniff Date: Mon, 26 Dec 2022 13:41:36 GMT Content-Length: 256 I1226 13:41:37.404716 1 util.go:124] Send.sendRequest got response with ContentLength 256, StatusCode 404 and responseBody length 256 I1226 13:41:37.404733 1 azure_privatednsclient.go:215] Received error in privatednszone.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/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 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:41:37.404883 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.02387755 request="private_dns_zones_get" resource_group="kubetest-dbvgcbg1" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I1226 13:41:37.404905 1 azure_storageaccount.go:210] 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 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:41:37.404914 1 azure_storageaccount.go:423] Creating private dns zone(privatelink.file.core.windows.net) in resourceGroup (kubetest-dbvgcbg1) (2022-12-26T13:41:37.4049752Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 Content-Type: application/json; charset=utf-8 User-Agent: Go/go1.19.4 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test Authorization: **REDACTED** (2022-12-26T13:41:37.4050255Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net?api-version=2018-09-01 ... skipping 140 lines ... X-Ms-Correlation-Request-Id: 84c8d81d-1a2d-4287-b5e5-6a7777b53c98 X-Ms-Routing-Request-Id: SOUTHCENTRALUS:20221226T134208Z:84c8d81d-1a2d-4287-b5e5-6a7777b53c98 Strict-Transport-Security: max-age=31536000; includeSubDomains Date: Mon, 26 Dec 2022 13:42:08 GMT Content-Length: 309 I1226 13:42:08.983858 1 util.go:124] Send.sendRequest got response with ContentLength 309, StatusCode 404 and responseBody length 309 I1226 13:42:08.983960 1 azure_virtualnetworklinksclient.go:212] Received error in virtualnetworklink.get.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink, error: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {"error":{"code":"ResourceNotFound","message":"The Resource 'Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink' under resource group 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:42:08.984190 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.098774054 request="virtual_network_links_get" resource_group="kubetest-dbvgcbg1" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="ResourceNotFound" I1226 13:42:08.984237 1 azure_storageaccount.go:220] get virtual link for vnet(k8s-vnet-24837443) 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/f236f77495ba142adb8b72d-vnetlink' under resource group 'kubetest-dbvgcbg1' was not found. For more details please go to https://aka.ms/ARMResourceNotFoundFix"}} I1226 13:42:08.984249 1 azure_storageaccount.go:438] Creating virtual link for vnet(f236f77495ba142adb8b72d-vnetlink) and DNS Zone(privatelink.file.core.windows.net) in resourceGroup(kubetest-dbvgcbg1) (2022-12-26T13:42:08.9844122Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink?api-version=2020-06-01 Content-Type: application/json; charset=utf-8 User-Agent: Go/go1.19.4 (amd64-linux) go-autorest/v14.2.1 file.csi.azure.com/e2e-29c8b4ced89f2da62a755e03a0c284ab0c6b1d8d e2e-test Authorization: **REDACTED** (2022-12-26T13:42:08.9846481Z) INFO: REQUEST: PUT https://management.azure.com/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-dbvgcbg1/providers/Microsoft.Network/privateDnsZones/privatelink.file.core.windows.net/virtualNetworkLinks/f236f77495ba142adb8b72d-vnetlink?api-version=2020-06-01 ... skipping 3699 lines ... Platform: linux/amd64 Streaming logs below: I1226 13:52:43.091840 1 azurefile.go:299] driver userAgent: file.csi.azure.com/v1.24.0 I1226 13:52:43.092004 1 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:52:43.092714 1 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:52:43.142829 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 I1226 13:52:43.142876 1 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:52:43.142891 1 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I1226 13:52:43.142926 1 azure.go:110] read cloud config from file: /etc/kubernetes/azure.json successfully I1226 13:52:43.144167 1 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:52:43.144237 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:52:43.144350 1 azure.go:790] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 ... skipping 75 lines ... Platform: windows/amd64 Streaming logs below: I1226 13:52:38.446981 7272 azurefile.go:299] driver userAgent: file.csi.azure.com/v1.24.0 I1226 13:52:38.453124 7272 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:52:38.459187 7272 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:52:38.520919 7272 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 I1226 13:52:38.520919 7272 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:52:38.520919 7272 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I1226 13:52:38.521893 7272 azure.go:110] read cloud config from file: C:\k\azure.json successfully I1226 13:52:38.527013 7272 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:52:38.527580 7272 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:52:38.528580 7272 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 83 lines ... Platform: windows/amd64 Streaming logs below: I1226 13:52:36.820732 4840 azurefile.go:299] driver userAgent: file.csi.azure.com/v1.24.0 I1226 13:52:36.827975 4840 azure.go:65] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I1226 13:52:36.836992 4840 azure.go:80] reading cloud config from secret kube-system/azure-cloud-provider I1226 13:52:36.896954 4840 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 I1226 13:52:36.896954 4840 azure.go:92] could not read cloud config from secret kube-system/azure-cloud-provider I1226 13:52:36.896954 4840 azure.go:102] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I1226 13:52:36.896954 4840 azure.go:110] read cloud config from file: C:\k\azure.json successfully I1226 13:52:36.898075 4840 azure_auth.go:245] Using AzurePublicCloud environment I1226 13:52:36.899205 4840 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I1226 13:52:36.901370 4840 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 473 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 57531 # 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 18022 # 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(kubetest-dbvgcbg1) returns 7 accounts [38;5;243m12/26/22 13:53:35.029[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 be able to unmount volume if volume is already deleted [file.csi.azure.com][0m[0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_unmount_tester.go:63[0m [38;5;9m[1mRan 23 of 37 Specs in 1827.462 seconds[0m [38;5;9m[1mFAIL![0m -- [38;5;10m[1m22 Passed[0m | [38;5;9m[1m1 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m14 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 (1827.47s) FAIL FAIL sigs.k8s.io/azurefile-csi-driver/test/e2e 1827.854s FAIL make: *** [Makefile:85: e2e-test] Error 1 2022/12/26 13:53:35 process.go:155: Step 'make e2e-test' finished in 35m12.407445311s 2022/12/26 13:53:35 aksengine_helpers.go:425: downloading /root/tmp3584716969/log-dump.sh from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh 2022/12/26 13:53:35 util.go:70: curl https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh 2022/12/26 13:53:35 process.go:153: Running: chmod +x /root/tmp3584716969/log-dump.sh 2022/12/26 13:53:35 process.go:155: Step 'chmod +x /root/tmp3584716969/log-dump.sh' finished in 3.741414ms 2022/12/26 13:53:35 aksengine_helpers.go:425: downloading /root/tmp3584716969/log-dump-daemonset.yaml from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump-daemonset.yaml ... skipping 110 lines ... Flags -d Detailed option, when used with list, dumps the json of the object Write-Progress : Win32 internal error "Access is denied" 0x5 occurred while reading the console output buffer. Contact Microsoft Customer Support Services. At C:\windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Archive\Microsoft.PowerShell.Archive.psm1:1132 char:9 + Write-Progress -Activity $cmdletName -Status $status -Percent ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 53 lines ... Flags -d Detailed option, when used with list, dumps the json of the object Write-Progress : Win32 internal error "Access is denied" 0x5 occurred while reading the console output buffer. Contact Microsoft Customer Support Services. At C:\windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Archive\Microsoft.PowerShell.Archive.psm1:1132 char:9 + Write-Progress -Activity $cmdletName -Status $status -Percent ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 8 lines ... Warning: Permanently added '2483k8s001' (ECDSA) to the list of known hosts. Collecting logs for vm 2483k8s002 Testing connection to host 2483k8s002. Warning: Permanently added 'kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com,20.118.83.173' (ECDSA) to the list of known hosts. Authorized uses only. All activity may be monitored and reported. channel 0: open failed: connect failed: Name or service not known stdio forwarding failed ssh_exchange_identification: Connection closed by remote host 2022/12/26 13:54:56 process.go:155: Step 'bash -c /root/tmp3584716969/win-ci-logs-collector.sh kubetest-dbvgcbg1.southcentralus.cloudapp.azure.com /root/tmp3584716969 /etc/ssh-key-secret/ssh-private' finished in 59.721126439s 2022/12/26 13:54:56 aksengine.go:1141: Deleting resource group: kubetest-dbvgcbg1. 2022/12/26 13:59:59 process.go:96: Saved XML output to /logs/artifacts/junit_runner.xml. 2022/12/26 13:59:59 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" 2022/12/26 14:00:01 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 1.48992883s 2022/12/26 14:00:01 main.go:328: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] + EXIT_VALUE=1 + set +o xtrace Cleaning up after docker in docker. ================================================================================ Cleaning up after docker bf11cd9719b6 ... skipping 4 lines ...