ci-kubernetes-e2e-azuredisk-capz-windows-2019 #1610676458605252608
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 2h0m |
| Revision | main |
... skipping 799 lines ... certificate.cert-manager.io "selfsigned-cert" deleted # Create secret for AzureClusterIdentity ./hack/create-identity-secret.sh make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' make[2]: Nothing to be done for 'kubectl'. make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' Error from server (NotFound): secrets "cluster-identity-secret" not found secret/cluster-identity-secret created secret/cluster-identity-secret labeled # Create customized cloud provider configs ./hack/create-custom-cloud-provider-config.sh make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' make[2]: Nothing to be done for 'kubectl'. ... skipping 219 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 100k 0 --:--:-- --:--:-- --:--:-- 100k 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 capzci.azurecr.io/azuredisk-csi:v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50 || make container-all push-manifest Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50 not found: manifest unknown: manifest tagged by "v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50" is not found make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver' CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.driverVersion=v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=5b34728159258d3729b6a7f9914dd0ffe6602e50 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-04T17:03:40Z -extldflags "-static"" -mod vendor -o _output/amd64/azurediskplugin.exe ./pkg/azurediskplugin 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 1804 lines ... type: string type: object oneOf: - required: ["persistentVolumeClaimName"] - required: ["volumeSnapshotContentName"] volumeSnapshotClassName: description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.' type: string required: - source type: object status: description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object. ... skipping 2 lines ... description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.' type: string creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown. format: date-time type: string error: description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: type: string description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$ x-kubernetes-int-or-string: true type: object required: - spec type: object ... skipping 60 lines ... type: string volumeSnapshotContentName: description: volumeSnapshotContentName specifies the name of a pre-existing VolumeSnapshotContent object representing an existing volume snapshot. This field should be set if the snapshot already exists and only needs a representation in Kubernetes. This field is immutable. type: string type: object volumeSnapshotClassName: description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.' type: string required: - source type: object status: description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object. ... skipping 2 lines ... description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.' type: string creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown. format: date-time type: string error: description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: type: string description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$ x-kubernetes-int-or-string: true type: object required: - spec type: object ... skipping 254 lines ... description: status represents the current information of a snapshot. properties: creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it indicates the creation time is unknown. The format of this field is a Unix nanoseconds time encoded as an int64. On Unix, the command `date +%s%N` returns the current time in nanoseconds since 1970-01-01 00:00:00 UTC. format: int64 type: integer error: description: error is the last observed error during snapshot creation, if any. Upon success after retry, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if a snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: description: restoreSize represents the complete size of the snapshot in bytes. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. format: int64 minimum: 0 type: integer snapshotHandle: description: snapshotHandle is the CSI "snapshot_id" of a snapshot on the underlying storage system. If not specified, it indicates that dynamic snapshot creation has either failed or it is still in progress. type: string type: object required: - spec type: object served: true ... skipping 108 lines ... description: status represents the current information of a snapshot. properties: creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it indicates the creation time is unknown. The format of this field is a Unix nanoseconds time encoded as an int64. On Unix, the command `date +%s%N` returns the current time in nanoseconds since 1970-01-01 00:00:00 UTC. format: int64 type: integer error: description: error is the last observed error during snapshot creation, if any. Upon success after retry, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if a snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: description: restoreSize represents the complete size of the snapshot in bytes. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. format: int64 minimum: 0 type: integer snapshotHandle: description: snapshotHandle is the CSI "snapshot_id" of a snapshot on the underlying storage system. If not specified, it indicates that dynamic snapshot creation has either failed or it is still in progress. type: string type: object required: - spec type: object served: true ... skipping 613 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' - '-feature-gates=RecoverVolumeExpansionFailure=true' - "-timeout=240s" env: - name: ADDRESS value: /csi/csi.sock volumeMounts: ... skipping 217 lines ... Jan 4 17:17:21.084: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-dpsq9] to have phase Bound Jan 4 17:17:21.194: INFO: PersistentVolumeClaim pvc-dpsq9 found and phase=Bound (109.444846ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:17:21.194[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:17:21.305[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:17:21.415[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:17:21.415[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 17:17:21.531[0m Jan 4 17:17:21.532: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-b4fzs" in namespace "azuredisk-8081" to be "Error status code" Jan 4 17:17:21.660: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 128.343831ms Jan 4 17:17:23.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.238358698s Jan 4 17:17:25.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 4.238388787s Jan 4 17:17:27.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 6.238562545s Jan 4 17:17:29.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 8.238758905s Jan 4 17:17:31.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 10.238034775s ... skipping 200 lines ... Jan 4 17:24:13.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 6m52.246410525s Jan 4 17:24:15.779: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=true. Elapsed: 6m54.247427949s Jan 4 17:24:17.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=true. Elapsed: 6m56.246675229s Jan 4 17:24:19.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=true. Elapsed: 6m58.246775225s Jan 4 17:24:21.780: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=false. Elapsed: 7m0.248443592s Jan 4 17:24:23.780: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=false. Elapsed: 7m2.247890571s Jan 4 17:24:25.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Failed", Reason="", readiness=false. Elapsed: 7m4.246175104s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 17:24:25.778[0m Jan 4 17:24:25.778: INFO: Pod "azuredisk-volume-tester-b4fzs" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 17:24:25.778[0m Jan 4 17:24:25.920: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-b4fzs" Jan 4 17:24:26.033: INFO: Pod azuredisk-volume-tester-b4fzs 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 79 lines ... Jan 4 17:17:21.084: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-dpsq9] to have phase Bound Jan 4 17:17:21.194: INFO: PersistentVolumeClaim pvc-dpsq9 found and phase=Bound (109.444846ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:17:21.194[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:17:21.305[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:17:21.415[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:17:21.415[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 17:17:21.531[0m Jan 4 17:17:21.532: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-b4fzs" in namespace "azuredisk-8081" to be "Error status code" Jan 4 17:17:21.660: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 128.343831ms Jan 4 17:17:23.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.238358698s Jan 4 17:17:25.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 4.238388787s Jan 4 17:17:27.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 6.238562545s Jan 4 17:17:29.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 8.238758905s Jan 4 17:17:31.770: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 10.238034775s ... skipping 200 lines ... Jan 4 17:24:13.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Pending", Reason="", readiness=false. Elapsed: 6m52.246410525s Jan 4 17:24:15.779: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=true. Elapsed: 6m54.247427949s Jan 4 17:24:17.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=true. Elapsed: 6m56.246675229s Jan 4 17:24:19.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=true. Elapsed: 6m58.246775225s Jan 4 17:24:21.780: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=false. Elapsed: 7m0.248443592s Jan 4 17:24:23.780: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Running", Reason="", readiness=false. Elapsed: 7m2.247890571s Jan 4 17:24:25.778: INFO: Pod "azuredisk-volume-tester-b4fzs": Phase="Failed", Reason="", readiness=false. Elapsed: 7m4.246175104s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 17:24:25.778[0m Jan 4 17:24:25.778: INFO: Pod "azuredisk-volume-tester-b4fzs" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 17:24:25.778[0m Jan 4 17:24:25.920: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-b4fzs" Jan 4 17:24:26.033: INFO: Pod azuredisk-volume-tester-b4fzs 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 137 lines ... [1mSTEP:[0m Successfully provisioned a shared disk volume: "/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/single-shared-disk" [38;5;243m01/04/23 17:25:07.65[0m [1mSTEP:[0m Destroying namespace "azuredisk-4728" for this suite. [38;5;243m01/04/23 17:25:08.619[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;243m------------------------------[0m [0mPre-Provisioned [38;5;243m[single-az][0m [1mshould fail when maxShares is invalid [disk.csi.azure.com][windows][0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:166[0m [1mSTEP:[0m Creating a kubernetes client [38;5;243m01/04/23 17:25:08.733[0m Jan 4 17:25:08.733: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig [1mSTEP:[0m Building a namespace api object, basename azuredisk [38;5;243m01/04/23 17:25:08.735[0m [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m01/04/23 17:25:09.062[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m01/04/23 17:25:09.278[0m ... skipping 2 lines ... [38;5;243m------------------------------[0m [38;5;10m• [0.877 seconds][0m Pre-Provisioned [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:38[0m [single-az] [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:71[0m should fail when maxShares is invalid [disk.csi.azure.com][windows] [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:166[0m [38;5;243mBegin Captured GinkgoWriter Output >>[0m [1mSTEP:[0m Creating a kubernetes client [38;5;243m01/04/23 17:25:08.733[0m Jan 4 17:25:08.733: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig [1mSTEP:[0m Building a namespace api object, basename azuredisk [38;5;243m01/04/23 17:25:08.735[0m ... skipping 88 lines ... Jan 4 17:25:22.024: INFO: PersistentVolumeClaim pvc-lkvbn found and phase=Bound (108.051254ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:25:22.024[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:25:22.133[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:25:22.242[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/04/23 17:25:22.403[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:25:35.582[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:25:35.697[0m Jan 4 17:25:35.697: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-wd8kr" in namespace "azuredisk-5194" to be "Succeeded or Failed" Jan 4 17:25:35.806: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 108.894019ms Jan 4 17:25:37.915: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218657983s Jan 4 17:25:39.916: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.218722083s Jan 4 17:25:41.916: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218724393s Jan 4 17:25:43.915: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.218570527s Jan 4 17:25:45.917: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220295555s ... skipping 278 lines ... Jan 4 17:35:03.922: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=true. Elapsed: 9m28.224757482s Jan 4 17:35:05.922: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=false. Elapsed: 9m30.225003702s Jan 4 17:35:07.923: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=false. Elapsed: 9m32.226460888s Jan 4 17:35:09.923: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=false. Elapsed: 9m34.225891101s Jan 4 17:35:11.923: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 9m36.226247919s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:35:11.923[0m Jan 4 17:35:11.924: INFO: Pod "azuredisk-volume-tester-wd8kr" satisfied condition "Succeeded or Failed" Jan 4 17:35:11.924: INFO: deleting Pod "azuredisk-5194"/"azuredisk-volume-tester-wd8kr" Jan 4 17:35:12.057: INFO: Pod azuredisk-volume-tester-wd8kr has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-wd8kr in namespace azuredisk-5194 [38;5;243m01/04/23 17:35:12.058[0m Jan 4 17:35:12.439: INFO: deleting PVC "azuredisk-5194"/"pvc-lkvbn" Jan 4 17:35:12.439: INFO: Deleting PersistentVolumeClaim "pvc-lkvbn" ... skipping 37 lines ... Jan 4 17:25:22.024: INFO: PersistentVolumeClaim pvc-lkvbn found and phase=Bound (108.051254ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:25:22.024[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:25:22.133[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:25:22.242[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/04/23 17:25:22.403[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:25:35.582[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:25:35.697[0m Jan 4 17:25:35.697: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-wd8kr" in namespace "azuredisk-5194" to be "Succeeded or Failed" Jan 4 17:25:35.806: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 108.894019ms Jan 4 17:25:37.915: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218657983s Jan 4 17:25:39.916: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.218722083s Jan 4 17:25:41.916: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218724393s Jan 4 17:25:43.915: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.218570527s Jan 4 17:25:45.917: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220295555s ... skipping 278 lines ... Jan 4 17:35:03.922: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=true. Elapsed: 9m28.224757482s Jan 4 17:35:05.922: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=false. Elapsed: 9m30.225003702s Jan 4 17:35:07.923: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=false. Elapsed: 9m32.226460888s Jan 4 17:35:09.923: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Running", Reason="", readiness=false. Elapsed: 9m34.225891101s Jan 4 17:35:11.923: INFO: Pod "azuredisk-volume-tester-wd8kr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 9m36.226247919s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:35:11.923[0m Jan 4 17:35:11.924: INFO: Pod "azuredisk-volume-tester-wd8kr" satisfied condition "Succeeded or Failed" Jan 4 17:35:11.924: INFO: deleting Pod "azuredisk-5194"/"azuredisk-volume-tester-wd8kr" Jan 4 17:35:12.057: INFO: Pod azuredisk-volume-tester-wd8kr has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-wd8kr in namespace azuredisk-5194 [38;5;243m01/04/23 17:35:12.058[0m Jan 4 17:35:12.439: INFO: deleting PVC "azuredisk-5194"/"pvc-lkvbn" Jan 4 17:35:12.439: INFO: Deleting PersistentVolumeClaim "pvc-lkvbn" ... skipping 68 lines ... Jan 4 17:35:48.032: INFO: PersistentVolumeClaim pvc-6p5sj found and phase=Bound (4.329351546s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:35:48.033[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:35:48.142[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:35:48.253[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:35:48.253[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:35:48.253[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:35:48.371[0m Jan 4 17:35:48.371: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fmdvg" in namespace "azuredisk-2888" to be "Succeeded or Failed" Jan 4 17:35:48.480: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 108.820329ms Jan 4 17:35:50.590: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218910821s Jan 4 17:35:52.591: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219344312s Jan 4 17:35:54.592: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.221217104s Jan 4 17:35:56.590: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.219152127s Jan 4 17:35:58.593: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.22154858s ... skipping 15 lines ... Jan 4 17:36:30.597: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=true. Elapsed: 42.225585102s Jan 4 17:36:32.597: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=true. Elapsed: 44.225749222s Jan 4 17:36:34.596: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=false. Elapsed: 46.225082429s Jan 4 17:36:36.599: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=false. Elapsed: 48.22733831s Jan 4 17:36:38.597: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 50.226157843s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:36:38.598[0m Jan 4 17:36:38.598: INFO: Pod "azuredisk-volume-tester-fmdvg" satisfied condition "Succeeded or Failed" Jan 4 17:36:38.598: INFO: deleting Pod "azuredisk-2888"/"azuredisk-volume-tester-fmdvg" Jan 4 17:36:38.735: INFO: Pod azuredisk-volume-tester-fmdvg has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-fmdvg in namespace azuredisk-2888 [38;5;243m01/04/23 17:36:38.735[0m Jan 4 17:36:38.870: INFO: deleting PVC "azuredisk-2888"/"pvc-6p5sj" Jan 4 17:36:38.870: INFO: Deleting PersistentVolumeClaim "pvc-6p5sj" ... skipping 39 lines ... Jan 4 17:35:48.032: INFO: PersistentVolumeClaim pvc-6p5sj found and phase=Bound (4.329351546s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:35:48.033[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:35:48.142[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:35:48.253[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:35:48.253[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:35:48.253[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:35:48.371[0m Jan 4 17:35:48.371: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fmdvg" in namespace "azuredisk-2888" to be "Succeeded or Failed" Jan 4 17:35:48.480: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 108.820329ms Jan 4 17:35:50.590: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218910821s Jan 4 17:35:52.591: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219344312s Jan 4 17:35:54.592: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.221217104s Jan 4 17:35:56.590: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.219152127s Jan 4 17:35:58.593: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.22154858s ... skipping 15 lines ... Jan 4 17:36:30.597: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=true. Elapsed: 42.225585102s Jan 4 17:36:32.597: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=true. Elapsed: 44.225749222s Jan 4 17:36:34.596: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=false. Elapsed: 46.225082429s Jan 4 17:36:36.599: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Running", Reason="", readiness=false. Elapsed: 48.22733831s Jan 4 17:36:38.597: INFO: Pod "azuredisk-volume-tester-fmdvg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 50.226157843s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:36:38.598[0m Jan 4 17:36:38.598: INFO: Pod "azuredisk-volume-tester-fmdvg" satisfied condition "Succeeded or Failed" Jan 4 17:36:38.598: INFO: deleting Pod "azuredisk-2888"/"azuredisk-volume-tester-fmdvg" Jan 4 17:36:38.735: INFO: Pod azuredisk-volume-tester-fmdvg has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-fmdvg in namespace azuredisk-2888 [38;5;243m01/04/23 17:36:38.735[0m Jan 4 17:36:38.870: INFO: deleting PVC "azuredisk-2888"/"pvc-6p5sj" Jan 4 17:36:38.870: INFO: Deleting PersistentVolumeClaim "pvc-6p5sj" ... skipping 37 lines ... Jan 4 17:37:24.311: INFO: PersistentVolumeClaim pvc-lvjrw found but phase is Pending instead of Bound. Jan 4 17:37:26.420: INFO: PersistentVolumeClaim pvc-lvjrw found and phase=Bound (4.328142313s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:37:26.42[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:37:26.528[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:37:26.637[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:37:26.637[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/04/23 17:37:26.751[0m Jan 4 17:37:26.751: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-n6f22" in namespace "azuredisk-156" to be "Succeeded or Failed" Jan 4 17:37:26.860: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 108.647417ms Jan 4 17:37:28.970: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218448864s Jan 4 17:37:30.972: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22026479s Jan 4 17:37:32.971: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219687125s Jan 4 17:37:34.970: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 8.218443538s Jan 4 17:37:36.971: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21969195s ... skipping 16 lines ... Jan 4 17:38:10.982: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=true. Elapsed: 44.230100382s Jan 4 17:38:12.976: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=true. Elapsed: 46.224731221s Jan 4 17:38:14.978: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=false. Elapsed: 48.226158305s Jan 4 17:38:16.977: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=false. Elapsed: 50.225963883s Jan 4 17:38:18.977: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Succeeded", Reason="", readiness=false. Elapsed: 52.225194808s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:38:18.977[0m Jan 4 17:38:18.977: INFO: Pod "azuredisk-volume-tester-n6f22" satisfied condition "Succeeded or Failed" Jan 4 17:38:18.977: INFO: deleting Pod "azuredisk-156"/"azuredisk-volume-tester-n6f22" Jan 4 17:38:19.109: INFO: Pod azuredisk-volume-tester-n6f22 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-n6f22 in namespace azuredisk-156 [38;5;243m01/04/23 17:38:19.109[0m Jan 4 17:38:19.233: INFO: deleting PVC "azuredisk-156"/"pvc-lvjrw" Jan 4 17:38:19.233: INFO: Deleting PersistentVolumeClaim "pvc-lvjrw" ... skipping 38 lines ... Jan 4 17:37:24.311: INFO: PersistentVolumeClaim pvc-lvjrw found but phase is Pending instead of Bound. Jan 4 17:37:26.420: INFO: PersistentVolumeClaim pvc-lvjrw found and phase=Bound (4.328142313s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:37:26.42[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:37:26.528[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:37:26.637[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:37:26.637[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/04/23 17:37:26.751[0m Jan 4 17:37:26.751: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-n6f22" in namespace "azuredisk-156" to be "Succeeded or Failed" Jan 4 17:37:26.860: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 108.647417ms Jan 4 17:37:28.970: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218448864s Jan 4 17:37:30.972: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22026479s Jan 4 17:37:32.971: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219687125s Jan 4 17:37:34.970: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 8.218443538s Jan 4 17:37:36.971: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21969195s ... skipping 16 lines ... Jan 4 17:38:10.982: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=true. Elapsed: 44.230100382s Jan 4 17:38:12.976: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=true. Elapsed: 46.224731221s Jan 4 17:38:14.978: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=false. Elapsed: 48.226158305s Jan 4 17:38:16.977: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Running", Reason="", readiness=false. Elapsed: 50.225963883s Jan 4 17:38:18.977: INFO: Pod "azuredisk-volume-tester-n6f22": Phase="Succeeded", Reason="", readiness=false. Elapsed: 52.225194808s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:38:18.977[0m Jan 4 17:38:18.977: INFO: Pod "azuredisk-volume-tester-n6f22" satisfied condition "Succeeded or Failed" Jan 4 17:38:18.977: INFO: deleting Pod "azuredisk-156"/"azuredisk-volume-tester-n6f22" Jan 4 17:38:19.109: INFO: Pod azuredisk-volume-tester-n6f22 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-n6f22 in namespace azuredisk-156 [38;5;243m01/04/23 17:38:19.109[0m Jan 4 17:38:19.233: INFO: deleting PVC "azuredisk-156"/"pvc-lvjrw" Jan 4 17:38:19.233: INFO: Deleting PersistentVolumeClaim "pvc-lvjrw" ... skipping 38 lines ... Jan 4 17:39:06.708: INFO: PersistentVolumeClaim pvc-8nvfk found and phase=Bound (4.329170048s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:39:06.708[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:39:06.817[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:39:06.925[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:39:06.925[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:39:06.925[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:39:07.042[0m Jan 4 17:39:07.043: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qcxbr" in namespace "azuredisk-1563" to be "Succeeded or Failed" Jan 4 17:39:07.150: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 107.422605ms Jan 4 17:39:09.260: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217714306s Jan 4 17:39:11.259: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21603921s Jan 4 17:39:13.261: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218062524s Jan 4 17:39:15.259: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.216230876s Jan 4 17:39:17.262: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.219133531s ... skipping 20 lines ... Jan 4 17:39:59.267: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=true. Elapsed: 52.224035091s Jan 4 17:40:01.266: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=true. Elapsed: 54.22290673s Jan 4 17:40:03.265: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=true. Elapsed: 56.222640124s Jan 4 17:40:05.267: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=false. Elapsed: 58.224057449s Jan 4 17:40:07.267: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.223868757s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:40:07.267[0m Jan 4 17:40:07.267: INFO: Pod "azuredisk-volume-tester-qcxbr" satisfied condition "Succeeded or Failed" Jan 4 17:40:07.267: INFO: deleting Pod "azuredisk-1563"/"azuredisk-volume-tester-qcxbr" Jan 4 17:40:07.398: INFO: Pod azuredisk-volume-tester-qcxbr has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-qcxbr in namespace azuredisk-1563 [38;5;243m01/04/23 17:40:07.398[0m Jan 4 17:40:07.528: INFO: deleting PVC "azuredisk-1563"/"pvc-8nvfk" Jan 4 17:40:07.528: INFO: Deleting PersistentVolumeClaim "pvc-8nvfk" ... skipping 39 lines ... Jan 4 17:39:06.708: INFO: PersistentVolumeClaim pvc-8nvfk found and phase=Bound (4.329170048s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:39:06.708[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:39:06.817[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:39:06.925[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:39:06.925[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:39:06.925[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:39:07.042[0m Jan 4 17:39:07.043: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qcxbr" in namespace "azuredisk-1563" to be "Succeeded or Failed" Jan 4 17:39:07.150: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 107.422605ms Jan 4 17:39:09.260: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217714306s Jan 4 17:39:11.259: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21603921s Jan 4 17:39:13.261: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218062524s Jan 4 17:39:15.259: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.216230876s Jan 4 17:39:17.262: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.219133531s ... skipping 20 lines ... Jan 4 17:39:59.267: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=true. Elapsed: 52.224035091s Jan 4 17:40:01.266: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=true. Elapsed: 54.22290673s Jan 4 17:40:03.265: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=true. Elapsed: 56.222640124s Jan 4 17:40:05.267: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Running", Reason="", readiness=false. Elapsed: 58.224057449s Jan 4 17:40:07.267: INFO: Pod "azuredisk-volume-tester-qcxbr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.223868757s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:40:07.267[0m Jan 4 17:40:07.267: INFO: Pod "azuredisk-volume-tester-qcxbr" satisfied condition "Succeeded or Failed" Jan 4 17:40:07.267: INFO: deleting Pod "azuredisk-1563"/"azuredisk-volume-tester-qcxbr" Jan 4 17:40:07.398: INFO: Pod azuredisk-volume-tester-qcxbr has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-qcxbr in namespace azuredisk-1563 [38;5;243m01/04/23 17:40:07.398[0m Jan 4 17:40:07.528: INFO: deleting PVC "azuredisk-1563"/"pvc-8nvfk" Jan 4 17:40:07.528: INFO: Deleting PersistentVolumeClaim "pvc-8nvfk" ... skipping 182 lines ... Jan 4 17:41:01.255: INFO: PersistentVolumeClaim pvc-mzmv9 found and phase=Bound (4.331073039s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:41:01.255[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:41:01.363[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:41:01.472[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:41:01.472[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:41:01.472[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 17:41:01.584[0m Jan 4 17:41:01.584: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zln89" in namespace "azuredisk-8010" to be "Error status code" Jan 4 17:41:01.693: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 108.784236ms Jan 4 17:41:03.802: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 2.21735225s Jan 4 17:41:05.807: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 4.222735788s Jan 4 17:41:07.802: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218055786s Jan 4 17:41:09.802: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 8.217995391s Jan 4 17:41:11.803: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 10.218452551s ... skipping 31 lines ... Jan 4 17:42:15.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 1m14.224321918s Jan 4 17:42:17.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m16.224613342s Jan 4 17:42:19.810: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m18.225517751s Jan 4 17:42:21.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m20.224294363s Jan 4 17:42:23.810: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m22.225513524s Jan 4 17:42:25.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=false. Elapsed: 1m24.224724461s Jan 4 17:42:27.810: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Failed", Reason="", readiness=false. Elapsed: 1m26.225866694s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 17:42:27.81[0m Jan 4 17:42:27.810: INFO: Pod "azuredisk-volume-tester-zln89" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 17:42:27.81[0m Jan 4 17:42:27.946: INFO: deleting Pod "azuredisk-8010"/"azuredisk-volume-tester-zln89" Jan 4 17:42:28.059: INFO: Pod azuredisk-volume-tester-zln89 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 54 lines ... Jan 4 17:41:01.255: INFO: PersistentVolumeClaim pvc-mzmv9 found and phase=Bound (4.331073039s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:41:01.255[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:41:01.363[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:41:01.472[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:41:01.472[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:41:01.472[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 17:41:01.584[0m Jan 4 17:41:01.584: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zln89" in namespace "azuredisk-8010" to be "Error status code" Jan 4 17:41:01.693: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 108.784236ms Jan 4 17:41:03.802: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 2.21735225s Jan 4 17:41:05.807: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 4.222735788s Jan 4 17:41:07.802: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218055786s Jan 4 17:41:09.802: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 8.217995391s Jan 4 17:41:11.803: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 10.218452551s ... skipping 31 lines ... Jan 4 17:42:15.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Pending", Reason="", readiness=false. Elapsed: 1m14.224321918s Jan 4 17:42:17.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m16.224613342s Jan 4 17:42:19.810: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m18.225517751s Jan 4 17:42:21.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m20.224294363s Jan 4 17:42:23.810: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=true. Elapsed: 1m22.225513524s Jan 4 17:42:25.809: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Running", Reason="", readiness=false. Elapsed: 1m24.224724461s Jan 4 17:42:27.810: INFO: Pod "azuredisk-volume-tester-zln89": Phase="Failed", Reason="", readiness=false. Elapsed: 1m26.225866694s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 17:42:27.81[0m Jan 4 17:42:27.810: INFO: Pod "azuredisk-volume-tester-zln89" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 17:42:27.81[0m Jan 4 17:42:27.946: INFO: deleting Pod "azuredisk-8010"/"azuredisk-volume-tester-zln89" Jan 4 17:42:28.059: INFO: Pod azuredisk-volume-tester-zln89 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 483 lines ... Jan 4 17:49:26.772: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-vcxbp-6dc989bfc5\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 4 17:49:28.774: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-vcxbp-6dc989bfc5\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 17:49:30.997[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 17:49:31.222[0m Jan 4 17:49:31.222: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 17:49:32.493: INFO: rc: 1 Jan 4 17:49:32.493: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 4 17:49:34.494: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 17:49:35.724: INFO: stderr: "" Jan 4 17:49:35.724: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/04/23 17:49:35.724[0m Jan 4 17:49:35.725: INFO: Deleting pod "azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl" in namespace "azuredisk-5894" ... skipping 114 lines ... Jan 4 17:49:26.772: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-vcxbp-6dc989bfc5\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 4 17:49:28.774: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 17, 48, 40, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-vcxbp-6dc989bfc5\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 17:49:30.997[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 17:49:31.222[0m Jan 4 17:49:31.222: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 17:49:32.493: INFO: rc: 1 Jan 4 17:49:32.493: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 4 17:49:34.494: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 17:49:35.724: INFO: stderr: "" Jan 4 17:49:35.724: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/04/23 17:49:35.724[0m Jan 4 17:49:35.725: INFO: Deleting pod "azuredisk-volume-tester-vcxbp-6dc989bfc5-crkxl" in namespace "azuredisk-5894" ... skipping 336 lines ... Jan 4 17:52:02.170: INFO: PersistentVolumeClaim pvc-zff6s found and phase=Bound (4.329592092s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:52:02.17[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:52:02.278[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:52:02.387[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:52:02.388[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:52:02.388[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:52:02.504[0m Jan 4 17:52:02.504: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-d7c5g" in namespace "azuredisk-9183" to be "Succeeded or Failed" Jan 4 17:52:02.620: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 115.50693ms Jan 4 17:52:04.736: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.231755925s Jan 4 17:52:06.737: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.233035206s Jan 4 17:52:08.737: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.232331102s Jan 4 17:52:10.735: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.231069686s Jan 4 17:52:12.737: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.232717072s ... skipping 23 lines ... Jan 4 17:53:00.735: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=true. Elapsed: 58.231161226s Jan 4 17:53:02.742: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.238203204s Jan 4 17:53:04.736: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.231535822s Jan 4 17:53:06.739: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=false. Elapsed: 1m4.235000217s Jan 4 17:53:08.736: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m6.231592872s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:53:08.736[0m Jan 4 17:53:08.736: INFO: Pod "azuredisk-volume-tester-d7c5g" satisfied condition "Succeeded or Failed" Jan 4 17:53:08.736: INFO: deleting Pod "azuredisk-9183"/"azuredisk-volume-tester-d7c5g" Jan 4 17:53:08.883: INFO: Pod azuredisk-volume-tester-d7c5g has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-d7c5g in namespace azuredisk-9183 [38;5;243m01/04/23 17:53:08.883[0m ... skipping 88 lines ... Jan 4 17:52:02.170: INFO: PersistentVolumeClaim pvc-zff6s found and phase=Bound (4.329592092s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:52:02.17[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:52:02.278[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:52:02.387[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:52:02.388[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:52:02.388[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:52:02.504[0m Jan 4 17:52:02.504: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-d7c5g" in namespace "azuredisk-9183" to be "Succeeded or Failed" Jan 4 17:52:02.620: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 115.50693ms Jan 4 17:52:04.736: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.231755925s Jan 4 17:52:06.737: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.233035206s Jan 4 17:52:08.737: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.232331102s Jan 4 17:52:10.735: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.231069686s Jan 4 17:52:12.737: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.232717072s ... skipping 23 lines ... Jan 4 17:53:00.735: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=true. Elapsed: 58.231161226s Jan 4 17:53:02.742: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.238203204s Jan 4 17:53:04.736: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.231535822s Jan 4 17:53:06.739: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Running", Reason="", readiness=false. Elapsed: 1m4.235000217s Jan 4 17:53:08.736: INFO: Pod "azuredisk-volume-tester-d7c5g": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m6.231592872s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:53:08.736[0m Jan 4 17:53:08.736: INFO: Pod "azuredisk-volume-tester-d7c5g" satisfied condition "Succeeded or Failed" Jan 4 17:53:08.736: INFO: deleting Pod "azuredisk-9183"/"azuredisk-volume-tester-d7c5g" Jan 4 17:53:08.883: INFO: Pod azuredisk-volume-tester-d7c5g has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-d7c5g in namespace azuredisk-9183 [38;5;243m01/04/23 17:53:08.883[0m ... skipping 96 lines ... Jan 4 17:54:22.462: INFO: PersistentVolumeClaim pvc-t8cg2 found but phase is Pending instead of Bound. Jan 4 17:54:24.571: INFO: PersistentVolumeClaim pvc-t8cg2 found and phase=Bound (4.325308983s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:54:24.571[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:54:24.68[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:54:24.789[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:54:24.789[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:54:24.903[0m Jan 4 17:54:24.904: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qq4qf" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 4 17:54:25.014: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 110.449025ms Jan 4 17:54:27.124: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220470886s Jan 4 17:54:29.123: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219916669s Jan 4 17:54:31.124: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219986331s Jan 4 17:54:33.123: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21910501s Jan 4 17:54:35.124: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220299383s ... skipping 17 lines ... Jan 4 17:55:11.131: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=true. Elapsed: 46.22712085s Jan 4 17:55:13.130: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=true. Elapsed: 48.226580164s Jan 4 17:55:15.130: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=false. Elapsed: 50.226336027s Jan 4 17:55:17.135: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=false. Elapsed: 52.231184092s Jan 4 17:55:19.131: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Succeeded", Reason="", readiness=false. Elapsed: 54.227101093s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:55:19.131[0m Jan 4 17:55:19.131: INFO: Pod "azuredisk-volume-tester-qq4qf" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 17:55:19.131[0m [1mSTEP:[0m Prow test resource group: capz-ukuy7t [38;5;243m01/04/23 17:55:19.132[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-f3a94a5a-8c58-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:55:19.132[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-f3a94a5a-8c58-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:55:22.07[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 17:55:22.071[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 17:55:22.071[0m ... skipping 11 lines ... Jan 4 17:55:41.978: INFO: PersistentVolumeClaim pvc-tqn7j found and phase=Bound (4.328401522s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:55:41.978[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:55:42.087[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:55:42.197[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:55:42.197[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 17:55:42.197[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:55:42.312[0m Jan 4 17:55:42.312: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6mz8s" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 4 17:55:42.420: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 108.241981ms Jan 4 17:55:44.531: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218968011s Jan 4 17:55:46.530: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 4.218521562s Jan 4 17:55:48.530: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218239609s Jan 4 17:55:50.537: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224614686s Jan 4 17:55:52.531: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 10.219043738s ... skipping 13 lines ... Jan 4 17:56:20.538: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=true. Elapsed: 38.22565977s Jan 4 17:56:22.536: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=false. Elapsed: 40.224457067s Jan 4 17:56:24.536: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=false. Elapsed: 42.223679809s Jan 4 17:56:26.535: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=false. Elapsed: 44.223264686s Jan 4 17:56:28.537: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Succeeded", Reason="", readiness=false. Elapsed: 46.224708107s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:56:28.537[0m Jan 4 17:56:28.537: INFO: Pod "azuredisk-volume-tester-6mz8s" satisfied condition "Succeeded or Failed" Jan 4 17:56:28.537: INFO: deleting Pod "azuredisk-1968"/"azuredisk-volume-tester-6mz8s" Jan 4 17:56:28.671: INFO: Pod azuredisk-volume-tester-6mz8s has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-6mz8s in namespace azuredisk-1968 [38;5;243m01/04/23 17:56:28.671[0m Jan 4 17:56:28.796: INFO: deleting PVC "azuredisk-1968"/"pvc-tqn7j" Jan 4 17:56:28.796: INFO: Deleting PersistentVolumeClaim "pvc-tqn7j" ... skipping 54 lines ... Jan 4 17:54:22.462: INFO: PersistentVolumeClaim pvc-t8cg2 found but phase is Pending instead of Bound. Jan 4 17:54:24.571: INFO: PersistentVolumeClaim pvc-t8cg2 found and phase=Bound (4.325308983s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:54:24.571[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:54:24.68[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:54:24.789[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:54:24.789[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:54:24.903[0m Jan 4 17:54:24.904: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qq4qf" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 4 17:54:25.014: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 110.449025ms Jan 4 17:54:27.124: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220470886s Jan 4 17:54:29.123: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219916669s Jan 4 17:54:31.124: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219986331s Jan 4 17:54:33.123: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21910501s Jan 4 17:54:35.124: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220299383s ... skipping 17 lines ... Jan 4 17:55:11.131: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=true. Elapsed: 46.22712085s Jan 4 17:55:13.130: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=true. Elapsed: 48.226580164s Jan 4 17:55:15.130: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=false. Elapsed: 50.226336027s Jan 4 17:55:17.135: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Running", Reason="", readiness=false. Elapsed: 52.231184092s Jan 4 17:55:19.131: INFO: Pod "azuredisk-volume-tester-qq4qf": Phase="Succeeded", Reason="", readiness=false. Elapsed: 54.227101093s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:55:19.131[0m Jan 4 17:55:19.131: INFO: Pod "azuredisk-volume-tester-qq4qf" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 17:55:19.131[0m [1mSTEP:[0m Prow test resource group: capz-ukuy7t [38;5;243m01/04/23 17:55:19.132[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-f3a94a5a-8c58-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:55:19.132[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-f3a94a5a-8c58-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:55:22.07[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 17:55:22.071[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 17:55:22.071[0m ... skipping 11 lines ... Jan 4 17:55:41.978: INFO: PersistentVolumeClaim pvc-tqn7j found and phase=Bound (4.328401522s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:55:41.978[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:55:42.087[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:55:42.197[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 17:55:42.197[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 17:55:42.197[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:55:42.312[0m Jan 4 17:55:42.312: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6mz8s" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 4 17:55:42.420: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 108.241981ms Jan 4 17:55:44.531: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218968011s Jan 4 17:55:46.530: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 4.218521562s Jan 4 17:55:48.530: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 6.218239609s Jan 4 17:55:50.537: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224614686s Jan 4 17:55:52.531: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Pending", Reason="", readiness=false. Elapsed: 10.219043738s ... skipping 13 lines ... Jan 4 17:56:20.538: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=true. Elapsed: 38.22565977s Jan 4 17:56:22.536: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=false. Elapsed: 40.224457067s Jan 4 17:56:24.536: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=false. Elapsed: 42.223679809s Jan 4 17:56:26.535: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Running", Reason="", readiness=false. Elapsed: 44.223264686s Jan 4 17:56:28.537: INFO: Pod "azuredisk-volume-tester-6mz8s": Phase="Succeeded", Reason="", readiness=false. Elapsed: 46.224708107s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:56:28.537[0m Jan 4 17:56:28.537: INFO: Pod "azuredisk-volume-tester-6mz8s" satisfied condition "Succeeded or Failed" Jan 4 17:56:28.537: INFO: deleting Pod "azuredisk-1968"/"azuredisk-volume-tester-6mz8s" Jan 4 17:56:28.671: INFO: Pod azuredisk-volume-tester-6mz8s has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-6mz8s in namespace azuredisk-1968 [38;5;243m01/04/23 17:56:28.671[0m Jan 4 17:56:28.796: INFO: deleting PVC "azuredisk-1968"/"pvc-tqn7j" Jan 4 17:56:28.796: INFO: Deleting PersistentVolumeClaim "pvc-tqn7j" ... skipping 53 lines ... Jan 4 17:58:44.541: INFO: PersistentVolumeClaim pvc-9qvx2 found but phase is Pending instead of Bound. Jan 4 17:58:46.650: INFO: PersistentVolumeClaim pvc-9qvx2 found and phase=Bound (4.327538606s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:58:46.65[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:58:46.759[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:58:46.869[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:58:46.869[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:58:46.984[0m Jan 4 17:58:46.984: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vkz66" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 4 17:58:47.094: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 109.118464ms Jan 4 17:58:49.204: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219674588s Jan 4 17:58:51.204: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219192657s Jan 4 17:58:53.205: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220088903s Jan 4 17:58:55.203: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21897001s Jan 4 17:58:57.204: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21988906s ... skipping 20 lines ... Jan 4 17:59:39.213: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=true. Elapsed: 52.228636789s Jan 4 17:59:41.212: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=true. Elapsed: 54.227501552s Jan 4 17:59:43.209: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=false. Elapsed: 56.224867144s Jan 4 17:59:45.210: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=false. Elapsed: 58.225265331s Jan 4 17:59:47.209: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.224191916s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:59:47.209[0m Jan 4 17:59:47.209: INFO: Pod "azuredisk-volume-tester-vkz66" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 17:59:47.209[0m [1mSTEP:[0m Prow test resource group: capz-ukuy7t [38;5;243m01/04/23 17:59:47.211[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-93731609-8c59-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:59:47.212[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-93731609-8c59-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:59:48.278[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 17:59:48.279[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 17:59:48.279[0m ... skipping 105 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 18:03:04.539[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 18:03:04.649[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 18:03:04.759[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 18:03:04.759[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/04/23 18:03:04.76[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 18:03:04.76[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 18:03:04.874[0m Jan 4 18:03:04.874: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zmm8f" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 4 18:03:04.983: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 108.69898ms Jan 4 18:03:07.094: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219110023s Jan 4 18:03:09.092: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.217193023s Jan 4 18:03:11.092: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.217699242s Jan 4 18:03:13.093: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21849598s Jan 4 18:03:15.096: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.221634998s ... skipping 16 lines ... Jan 4 18:03:49.102: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=true. Elapsed: 44.227764781s Jan 4 18:03:51.101: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=false. Elapsed: 46.226219315s Jan 4 18:03:53.101: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=false. Elapsed: 48.226020059s Jan 4 18:03:55.101: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=false. Elapsed: 50.226338243s Jan 4 18:03:57.107: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 52.232156086s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 18:03:57.107[0m Jan 4 18:03:57.107: INFO: Pod "azuredisk-volume-tester-zmm8f" satisfied condition "Succeeded or Failed" Jan 4 18:03:57.107: INFO: deleting Pod "azuredisk-4657"/"azuredisk-volume-tester-zmm8f" Jan 4 18:03:57.245: INFO: Pod azuredisk-volume-tester-zmm8f has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-zmm8f in namespace azuredisk-4657 [38;5;243m01/04/23 18:03:57.245[0m Jan 4 18:03:57.374: INFO: deleting PVC "azuredisk-4657"/"pvc-9zs42" Jan 4 18:03:57.374: INFO: Deleting PersistentVolumeClaim "pvc-9zs42" ... skipping 57 lines ... Jan 4 17:58:44.541: INFO: PersistentVolumeClaim pvc-9qvx2 found but phase is Pending instead of Bound. Jan 4 17:58:46.650: INFO: PersistentVolumeClaim pvc-9qvx2 found and phase=Bound (4.327538606s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 17:58:46.65[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 17:58:46.759[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 17:58:46.869[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 17:58:46.869[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 17:58:46.984[0m Jan 4 17:58:46.984: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vkz66" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 4 17:58:47.094: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 109.118464ms Jan 4 17:58:49.204: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219674588s Jan 4 17:58:51.204: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219192657s Jan 4 17:58:53.205: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220088903s Jan 4 17:58:55.203: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21897001s Jan 4 17:58:57.204: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21988906s ... skipping 20 lines ... Jan 4 17:59:39.213: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=true. Elapsed: 52.228636789s Jan 4 17:59:41.212: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=true. Elapsed: 54.227501552s Jan 4 17:59:43.209: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=false. Elapsed: 56.224867144s Jan 4 17:59:45.210: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Running", Reason="", readiness=false. Elapsed: 58.225265331s Jan 4 17:59:47.209: INFO: Pod "azuredisk-volume-tester-vkz66": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.224191916s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 17:59:47.209[0m Jan 4 17:59:47.209: INFO: Pod "azuredisk-volume-tester-vkz66" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 17:59:47.209[0m [1mSTEP:[0m Prow test resource group: capz-ukuy7t [38;5;243m01/04/23 17:59:47.211[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-93731609-8c59-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:59:47.212[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-93731609-8c59-11ed-b104-2e434a091b88 [38;5;243m01/04/23 17:59:48.278[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 17:59:48.279[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 17:59:48.279[0m ... skipping 105 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 18:03:04.539[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 18:03:04.649[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 18:03:04.759[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 18:03:04.759[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/04/23 18:03:04.76[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 18:03:04.76[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 18:03:04.874[0m Jan 4 18:03:04.874: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zmm8f" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 4 18:03:04.983: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 108.69898ms Jan 4 18:03:07.094: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219110023s Jan 4 18:03:09.092: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.217193023s Jan 4 18:03:11.092: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.217699242s Jan 4 18:03:13.093: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21849598s Jan 4 18:03:15.096: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.221634998s ... skipping 16 lines ... Jan 4 18:03:49.102: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=true. Elapsed: 44.227764781s Jan 4 18:03:51.101: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=false. Elapsed: 46.226219315s Jan 4 18:03:53.101: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=false. Elapsed: 48.226020059s Jan 4 18:03:55.101: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Running", Reason="", readiness=false. Elapsed: 50.226338243s Jan 4 18:03:57.107: INFO: Pod "azuredisk-volume-tester-zmm8f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 52.232156086s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 18:03:57.107[0m Jan 4 18:03:57.107: INFO: Pod "azuredisk-volume-tester-zmm8f" satisfied condition "Succeeded or Failed" Jan 4 18:03:57.107: INFO: deleting Pod "azuredisk-4657"/"azuredisk-volume-tester-zmm8f" Jan 4 18:03:57.245: INFO: Pod azuredisk-volume-tester-zmm8f has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-zmm8f in namespace azuredisk-4657 [38;5;243m01/04/23 18:03:57.245[0m Jan 4 18:03:57.374: INFO: deleting PVC "azuredisk-4657"/"pvc-9zs42" Jan 4 18:03:57.374: INFO: Deleting PersistentVolumeClaim "pvc-9zs42" ... skipping 80 lines ... Jan 4 18:06:23.917: INFO: PersistentVolumeClaim pvc-b86bn found but phase is Pending instead of Bound. Jan 4 18:06:26.027: INFO: PersistentVolumeClaim pvc-b86bn found and phase=Bound (4.330407218s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 18:06:26.027[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 18:06:26.138[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 18:06:26.248[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 18:06:26.248[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 18:06:26.362[0m Jan 4 18:06:26.362: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p5kzz" in namespace "azuredisk-1359" to be "Succeeded or Failed" Jan 4 18:06:26.493: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 130.181882ms Jan 4 18:06:28.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.247073093s Jan 4 18:06:30.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.248105944s Jan 4 18:06:32.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.247010082s Jan 4 18:06:34.611: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.248780531s Jan 4 18:06:36.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.246698444s ... skipping 30 lines ... Jan 4 18:07:38.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=true. Elapsed: 1m12.247979546s Jan 4 18:07:40.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=true. Elapsed: 1m14.24736108s Jan 4 18:07:42.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=true. Elapsed: 1m16.247664547s Jan 4 18:07:44.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=false. Elapsed: 1m18.247496565s Jan 4 18:07:46.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m20.246736068s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 18:07:46.609[0m Jan 4 18:07:46.609: INFO: Pod "azuredisk-volume-tester-p5kzz" satisfied condition "Succeeded or Failed" Jan 4 18:07:46.610: INFO: deleting Pod "azuredisk-1359"/"azuredisk-volume-tester-p5kzz" Jan 4 18:07:46.746: INFO: Pod azuredisk-volume-tester-p5kzz has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-p5kzz in namespace azuredisk-1359 [38;5;243m01/04/23 18:07:46.746[0m Jan 4 18:07:46.876: INFO: deleting PVC "azuredisk-1359"/"pvc-b86bn" Jan 4 18:07:46.876: INFO: Deleting PersistentVolumeClaim "pvc-b86bn" ... skipping 88 lines ... Jan 4 18:06:23.917: INFO: PersistentVolumeClaim pvc-b86bn found but phase is Pending instead of Bound. Jan 4 18:06:26.027: INFO: PersistentVolumeClaim pvc-b86bn found and phase=Bound (4.330407218s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 18:06:26.027[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 18:06:26.138[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 18:06:26.248[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 18:06:26.248[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 18:06:26.362[0m Jan 4 18:06:26.362: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p5kzz" in namespace "azuredisk-1359" to be "Succeeded or Failed" Jan 4 18:06:26.493: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 130.181882ms Jan 4 18:06:28.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.247073093s Jan 4 18:06:30.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.248105944s Jan 4 18:06:32.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.247010082s Jan 4 18:06:34.611: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.248780531s Jan 4 18:06:36.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.246698444s ... skipping 30 lines ... Jan 4 18:07:38.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=true. Elapsed: 1m12.247979546s Jan 4 18:07:40.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=true. Elapsed: 1m14.24736108s Jan 4 18:07:42.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=true. Elapsed: 1m16.247664547s Jan 4 18:07:44.610: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Running", Reason="", readiness=false. Elapsed: 1m18.247496565s Jan 4 18:07:46.609: INFO: Pod "azuredisk-volume-tester-p5kzz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m20.246736068s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 18:07:46.609[0m Jan 4 18:07:46.609: INFO: Pod "azuredisk-volume-tester-p5kzz" satisfied condition "Succeeded or Failed" Jan 4 18:07:46.610: INFO: deleting Pod "azuredisk-1359"/"azuredisk-volume-tester-p5kzz" Jan 4 18:07:46.746: INFO: Pod azuredisk-volume-tester-p5kzz has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-p5kzz in namespace azuredisk-1359 [38;5;243m01/04/23 18:07:46.746[0m Jan 4 18:07:46.876: INFO: deleting PVC "azuredisk-1359"/"pvc-b86bn" Jan 4 18:07:46.876: INFO: Deleting PersistentVolumeClaim "pvc-b86bn" ... skipping 597 lines ... I0104 18:17:25.270438 41313 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0104 18:17:27.272216 41313 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 18:17:27.389[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 18:17:27.507[0m Jan 4 18:17:27.507: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-8470 exec azuredisk-volume-tester-9q42r-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 18:17:28.777: INFO: rc: 1 Jan 4 18:17:28.777: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-9q42r-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-8470 exec azuredisk-volume-tester-9q42r-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 4 18:17:30.777: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-8470 exec azuredisk-volume-tester-9q42r-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 18:17:32.014: INFO: stderr: "" Jan 4 18:17:32.014: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/04/23 18:17:32.014[0m Jan 4 18:17:32.014: INFO: Deleting pod "azuredisk-volume-tester-9q42r-0" in namespace "azuredisk-8470" ... skipping 53 lines ... I0104 18:17:25.270438 41313 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0104 18:17:27.272216 41313 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 18:17:27.389[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 18:17:27.507[0m Jan 4 18:17:27.507: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-8470 exec azuredisk-volume-tester-9q42r-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 18:17:28.777: INFO: rc: 1 Jan 4 18:17:28.777: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-9q42r-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-8470 exec azuredisk-volume-tester-9q42r-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 4 18:17:30.777: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-8470 exec azuredisk-volume-tester-9q42r-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 18:17:32.014: INFO: stderr: "" Jan 4 18:17:32.014: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/04/23 18:17:32.014[0m Jan 4 18:17:32.014: INFO: Deleting pod "azuredisk-volume-tester-9q42r-0" in namespace "azuredisk-8470" ... skipping 225 lines ... Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0104 17:16:52.520179 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50 e2e-test I0104 17:16:52.520898 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0104 17:16:52.529916 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 8 milliseconds I0104 17:16:52.530372 1 azure_disk_utils.go:169] 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 I0104 17:16:52.530395 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 17:16:52.530402 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0104 17:16:52.530428 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0104 17:16:52.531009 1 azure_auth.go:245] Using AzurePublicCloud environment I0104 17:16:52.531051 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 17:16:52.531226 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0104 17:16:52.531291 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0104 17:16:52.531377 1 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0104 17:16:52.531408 1 azuredisk.go:192] disable UseInstanceMetadata for controller I0104 17:16:52.531436 1 azuredisk.go:204] cloud: AzurePublicCloud, location: westeurope, rg: capz-ukuy7t, VMType: vmss, PrimaryScaleSetName: , PrimaryAvailabilitySetName: , DisableAvailabilitySetNodes: false I0104 17:16:52.535868 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount893972688' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount893972688: must be superuser to unmount. I0104 17:16:52.535890 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0104 17:16:52.535955 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0104 17:16:52.535963 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0104 17:16:52.535968 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0104 17:16:52.535972 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0104 17:16:52.535990 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 199 lines ... I0104 17:25:56.459304 1 azure_controller_standard.go:236] azureDisk - update(capz-ukuy7t): vm(capz-ukuy-8hhhg) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-ukuy7t/providers/microsoft.compute/disks/reattach-disk-multiple-nodes:reattach-disk-multiple-nodes]) returned with <nil> I0104 17:25:56.459500 1 azure_controller_standard.go:126] DeleteCacheForNode(capz-ukuy-8hhhg) successfully I0104 17:25:56.459521 1 azure_controller_standard.go:272] updateCache(capz-ukuy-8hhhg) successfully I0104 17:25:56.459531 1 azure_controller_common.go:422] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded I0104 17:25:56.459565 1 controllerserver.go:425] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-ukuy-m8ll4 again I0104 17:25:56.459601 1 azure_controller_common.go:194] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-ukuy-8hhhg, could not be attached to node(capz-ukuy-m8ll4) E0104 17:25:56.459664 1 controllerserver.go:429] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-ukuy-m8ll4 failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/virtualMachines/capz-ukuy-8hhhg), could not be attached to node(capz-ukuy-m8ll4) I0104 17:25:56.459908 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=20.720008986 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-ukuy7t" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="capz-ukuy-m8ll4" result_code="failed_csi_driver_controller_publish_volume" E0104 17:25:56.459934 1 utils.go:82] GRPC error: rpc error: code = Internal desc = Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-ukuy-m8ll4 failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/virtualMachines/capz-ukuy-8hhhg), could not be attached to node(capz-ukuy-m8ll4) I0104 17:25:56.471445 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume I0104 17:25:56.471702 1 utils.go:78] GRPC request: {"node_id":"capz-ukuy-m8ll4","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"cachingMode":"None","requestedsizegib":"10","skuName":"Premium_LRS"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"} I0104 17:25:56.505536 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 972 I0104 17:25:56.505932 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.03376685 request="disks_get" resource_group="capz-ukuy7t" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="" I0104 17:25:56.505985 1 controllerserver.go:383] GetDiskLun returned: cannot find Lun for disk reattach-disk-multiple-nodes. Initiating attaching volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-ukuy-m8ll4 (vmState Succeeded). I0104 17:25:56.505998 1 controllerserver.go:408] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-ukuy-m8ll4 ... skipping 152 lines ... I0104 17:37:17.494847 1 utils.go:78] GRPC request: {} I0104 17:37:17.495439 1 utils.go:84] GRPC response: {"ready":{"value":true}} I0104 17:37:22.050952 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0104 17:37:22.051189 1 utils.go:78] GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.disk.csi.azure.com/zone":""}}],"requisite":[{"segments":{"topology.disk.csi.azure.com/zone":""}}]},"capacity_range":{"required_bytes":10737418240},"name":"pvc-c35aa94e-bc94-4488-8868-4617ac451d5a","parameters":{"csi.storage.k8s.io/pv/name":"pvc-c35aa94e-bc94-4488-8868-4617ac451d5a","csi.storage.k8s.io/pvc/name":"pvc-lvjrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-156","enableAsyncAttach":"false","networkAccessPolicy":"DenyAll","skuName":"Standard_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0104 17:37:22.051961 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0104 17:37:22.065062 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 11 milliseconds I0104 17:37:22.065298 1 azure_disk_utils.go:169] 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 I0104 17:37:22.065589 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 17:37:22.065673 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0104 17:37:22.065760 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0104 17:37:22.066134 1 azure_auth.go:245] Using AzurePublicCloud environment I0104 17:37:22.066286 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 17:37:22.066393 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 59 lines ... I0104 17:38:55.567909 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.234496148 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-ukuy7t" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/pvc-c35aa94e-bc94-4488-8868-4617ac451d5a" result_code="succeeded" I0104 17:38:55.568118 1 utils.go:84] GRPC response: {} I0104 17:39:02.339957 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0104 17:39:02.340190 1 utils.go:78] GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.disk.csi.azure.com/zone":""}}],"requisite":[{"segments":{"topology.disk.csi.azure.com/zone":""}}]},"capacity_range":{"required_bytes":1099511627776},"name":"pvc-9759eb2b-fdf3-4992-8bd8-93424e219679","parameters":{"csi.storage.k8s.io/pv/name":"pvc-9759eb2b-fdf3-4992-8bd8-93424e219679","csi.storage.k8s.io/pvc/name":"pvc-8nvfk","csi.storage.k8s.io/pvc/namespace":"azuredisk-1563","enableAsyncAttach":"false","enableBursting":"true","perfProfile":"Basic","skuName":"Premium_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0104 17:39:02.340907 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0104 17:39:02.349180 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 7 milliseconds I0104 17:39:02.349734 1 azure_disk_utils.go:169] 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 I0104 17:39:02.349891 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 17:39:02.349912 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0104 17:39:02.349941 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0104 17:39:02.350295 1 azure_auth.go:245] Using AzurePublicCloud environment I0104 17:39:02.350358 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 17:39:02.350398 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 1734 lines ... Go Version: go1.19.4 Platform: windows/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0104 17:17:07.818722 2856 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50 e2e-test W0104 17:17:07.820715 2856 azure_disk_utils.go:230] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified. I0104 17:17:07.821223 2856 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 17:17:07.821223 2856 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0104 17:17:07.821223 2856 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0104 17:17:07.823222 2856 azure_auth.go:245] Using AzurePublicCloud environment I0104 17:17:07.824227 2856 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 17:17:07.828222 2856 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 20 lines ... I0104 17:17:07.984231 2856 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50"} I0104 17:17:08.440195 2856 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo I0104 17:17:08.440195 2856 utils.go:78] GRPC request: {} I0104 17:17:08.440195 2856 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50"} I0104 17:17:08.770378 2856 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo I0104 17:17:08.770875 2856 utils.go:78] GRPC request: {} I0104 17:17:08.804919 2856 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0104 17:17:08.804919 2856 nodeserver.go:370] NodeGetInfo: nodeName(capz-ukuy-m8ll4), VM Size(Standard_D4s_v3) I0104 17:17:08.804919 2856 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8 I0104 17:17:08.804919 2856 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-ukuy-m8ll4"} I0104 17:17:47.540894 2856 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0104 17:17:47.541393 2856 utils.go:78] GRPC request: {} I0104 17:17:47.541393 2856 utils.go:84] GRPC response: {"ready":{"value":true}} ... skipping 983 lines ... Go Version: go1.19.4 Platform: windows/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0104 17:17:23.181369 5744 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50 e2e-test W0104 17:17:23.182798 5744 azure_disk_utils.go:230] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified. I0104 17:17:23.183368 5744 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 17:17:23.183368 5744 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0104 17:17:23.183486 5744 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0104 17:17:23.184168 5744 azure_auth.go:245] Using AzurePublicCloud environment I0104 17:17:23.184168 5744 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 17:17:23.188357 5744 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 20 lines ... I0104 17:17:23.286407 5744 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50"} I0104 17:17:23.788254 5744 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo I0104 17:17:23.788652 5744 utils.go:78] GRPC request: {} I0104 17:17:23.789367 5744 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-5b34728159258d3729b6a7f9914dd0ffe6602e50"} I0104 17:17:24.573514 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo I0104 17:17:24.573514 5744 utils.go:78] GRPC request: {} I0104 17:17:24.606368 5744 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0104 17:17:24.606418 5744 nodeserver.go:370] NodeGetInfo: nodeName(capz-ukuy-8hhhg), VM Size(Standard_D4s_v3) I0104 17:17:24.606418 5744 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8 I0104 17:17:24.606418 5744 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-ukuy-8hhhg"} I0104 17:17:57.435333 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities I0104 17:17:57.435333 5744 utils.go:78] GRPC request: {} I0104 17:17:57.435889 5744 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]} ... skipping 575 lines ... I0104 17:53:06.806204 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0104 17:53:06.806204 5744 utils.go:78] GRPC request: {"staging_target_path":"\\var\\lib\\kubelet\\plugins\\kubernetes.io\\csi\\disk.csi.azure.com\\93fbe9ccabcb0747b4d342544a91eb840bedfc58ab012a4b8504edc0ac963b4a\\globalmount","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/pvc-9be6703c-43f0-487f-b017-7ba87f140812"} I0104 17:53:06.806204 5744 nodeserver.go:201] NodeUnstageVolume: unmounting \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\93fbe9ccabcb0747b4d342544a91eb840bedfc58ab012a4b8504edc0ac963b4a\globalmount I0104 17:53:07.329826 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0104 17:53:07.329826 5744 utils.go:78] GRPC request: {"target_path":"c:\\var\\lib\\kubelet\\pods\\7ae8d692-239a-4e63-89b1-7233a3c4a86b\\volumes\\kubernetes.io~csi\\pvc-b70212c0-3d54-4454-9157-809465e367cf\\mount","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/pvc-b70212c0-3d54-4454-9157-809465e367cf"} I0104 17:53:07.329826 5744 nodeserver.go:301] NodeUnpublishVolume: unmounting volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/pvc-b70212c0-3d54-4454-9157-809465e367cf on c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc-b70212c0-3d54-4454-9157-809465e367cf\mount W0104 17:53:08.131237 5744 safe_mounter_windows.go:125] GetVolumeIDFromTargetPath(c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc-b70212c0-3d54-4454-9157-809465e367cf\mount) failed with error: rpc error: code = Unknown desc = error getting the volume for the mount c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc-b70212c0-3d54-4454-9157-809465e367cf\mount, internal error error getting volume from mount. cmd: (Get-Item -Path Get-Item : Cannot find path 'C:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc -b70212c0-3d54-4454-9157-809465e367cf\mount' because it does not exist. At line:1 char:2 + (Get-Item -Path c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + CategoryInfo : ObjectNotFound: (C:\var\lib\kube...465e367cf\mount:String) [Get-Item], ItemNotFoundExcep tion ... skipping 37 lines ... + ... d : PathNotFound,Microsoft.PowerShell.Commands.GetItemCommand).Target + ~ Unexpected token ')' in expression or statement. + CategoryInfo : ParserError: (:) [], ParentContainsErrorRecordException + FullyQualifiedErrorId : MissingEndParenthesisInExpression , error: exit status 1, response: <nil> I0104 17:53:08.132223 5744 nodeserver.go:307] NodeUnpublishVolume: unmount volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/pvc-b70212c0-3d54-4454-9157-809465e367cf on c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc-b70212c0-3d54-4454-9157-809465e367cf\mount successfully I0104 17:53:08.132223 5744 utils.go:84] GRPC response: {} I0104 17:53:08.191493 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities I0104 17:53:08.191493 5744 utils.go:78] GRPC request: {} I0104 17:53:08.191493 5744 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]} I0104 17:53:08.193443 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume ... skipping 6 lines ... I0104 17:53:09.853653 5744 utils.go:77] GRPC call: /csi.v1.Node/NodeGetVolumeStats I0104 17:53:09.853653 5744 utils.go:78] GRPC request: {"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-ukuy7t/providers/Microsoft.Compute/disks/pvc-b70212c0-3d54-4454-9157-809465e367cf","volume_path":"c:\\var\\lib\\kubelet\\pods\\7ae8d692-239a-4e63-89b1-7233a3c4a86b\\volumes\\kubernetes.io~csi\\pvc-b70212c0-3d54-4454-9157-809465e367cf\\mount"} I0104 17:53:10.443264 5744 nodeserver.go:206] NodeUnstageVolume: unmount \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\ee3ebdaa356a12005aaa64cd002e17803be74e7374c9ef6543c2e35b1f1b3063\globalmount successfully I0104 17:53:10.443264 5744 utils.go:84] GRPC response: {} I0104 17:53:10.509080 5744 nodeserver.go:206] NodeUnstageVolume: unmount \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\93fbe9ccabcb0747b4d342544a91eb840bedfc58ab012a4b8504edc0ac963b4a\globalmount successfully I0104 17:53:10.509080 5744 utils.go:84] GRPC response: {} E0104 17:53:10.622068 5744 utils.go:82] GRPC error: GetVolumeIDFromMount(c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc-b70212c0-3d54-4454-9157-809465e367cf\mount) failed with error: rpc error: code = Unknown desc = error getting the volume for the mount c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc-b70212c0-3d54-4454-9157-809465e367cf\mount, internal error error getting volume from mount. cmd: (Get-Item -Path Get-Item : Cannot find path 'C:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a3c4a86b\volumes\kubernetes.io~csi\pvc -b70212c0-3d54-4454-9157-809465e367cf\mount' because it does not exist. At line:1 char:2 + (Get-Item -Path c:\var\lib\kubelet\pods\7ae8d692-239a-4e63-89b1-7233a ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + CategoryInfo : ObjectNotFound: (C:\var\lib\kube...465e367cf\mount:String) [Get-Item], ItemNotFoundExcep tion ... skipping 37 lines ... + ... d : PathNotFound,Microsoft.PowerShell.Commands.GetItemCommand).Target + ~ Unexpected token ')' in expression or statement. + CategoryInfo : ParserError: (:) [], ParentContainsErrorRecordException + FullyQualifiedErrorId : MissingEndParenthesisInExpression , error: exit status 1, response: <nil> I0104 17:53:11.199683 5744 nodeserver.go:206] NodeUnstageVolume: unmount \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\9e4f4ee563c31bbfe4cf980186dc5fcfbcc243252a5c644df272c4739d4be722\globalmount successfully I0104 17:53:11.199683 5744 utils.go:84] GRPC response: {} I0104 17:53:17.727834 5744 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0104 17:53:17.727834 5744 utils.go:78] GRPC request: {} I0104 17:53:17.727834 5744 utils.go:84] GRPC response: {"ready":{"value":true}} I0104 17:53:47.722987 5744 utils.go:77] GRPC call: /csi.v1.Identity/Probe ... skipping 944 lines ... cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 34 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 34 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 34 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 34 cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 556.189392977 cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 34 # HELP cloudprovider_azure_op_failure_count [ALPHA] Number of failed Azure service operations # TYPE cloudprovider_azure_op_failure_count counter cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-ukuy7t",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1 # HELP disabled_metric_total [ALPHA] The count of disabled metrics. # TYPE disabled_metric_total counter disabled_metric_total 0 # HELP go_cgo_go_to_c_calls_calls_total Count of calls made from Go to C by the current process. ... skipping 67 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 56761 # 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 28687 # 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 271 lines ... [38;5;10m[AfterSuite] PASSED [156.246 seconds][0m [AfterSuite] [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/suite_test.go:165[0m [38;5;243m------------------------------[0m [38;5;10m[1mRan 22 of 66 Specs in 4662.568 seconds[0m [38;5;10m[1mSUCCESS![0m -- [38;5;10m[1m22 Passed[0m | [38;5;9m[1m0 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m44 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 ... skipping 43 lines ... Jan 4 18:23:55.731: INFO: Collecting logs for Windows node capz-ukuy-m8ll4 in cluster capz-ukuy7t in namespace default Jan 4 18:25:33.424: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-ukuy-m8ll4 to /logs/artifacts/clusters/capz-ukuy7t/machines/capz-ukuy7t-md-win-56696cdc56-6zc5n/crashdumps.tar Jan 4 18:25:37.031: INFO: Collecting boot logs for AzureMachine capz-ukuy7t-md-win-m8ll4 Failed to get logs for Machine capz-ukuy7t-md-win-56696cdc56-6zc5n, Cluster default/capz-ukuy7t: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1 Jan 4 18:25:38.387: INFO: Collecting logs for Windows node capz-ukuy-8hhhg in cluster capz-ukuy7t in namespace default Jan 4 18:27:10.938: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-ukuy-8hhhg to /logs/artifacts/clusters/capz-ukuy7t/machines/capz-ukuy7t-md-win-56696cdc56-flzhm/crashdumps.tar Jan 4 18:27:14.529: INFO: Collecting boot logs for AzureMachine capz-ukuy7t-md-win-8hhhg Failed to get logs for Machine capz-ukuy7t-md-win-56696cdc56-flzhm, Cluster default/capz-ukuy7t: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1 Jan 4 18:27:16.231: INFO: Dumping workload cluster default/capz-ukuy7t kube-system pod logs Jan 4 18:27:17.780: INFO: Collecting events for Pod calico-apiserver/calico-apiserver-68757cd48d-r68fq Jan 4 18:27:17.781: INFO: Creating log watcher for controller calico-apiserver/calico-apiserver-68757cd48d-r68fq, container calico-apiserver Jan 4 18:27:17.795: INFO: Creating log watcher for controller calico-apiserver/calico-apiserver-68757cd48d-n5gsn, container calico-apiserver Jan 4 18:27:17.780: INFO: Collecting events for Pod calico-apiserver/calico-apiserver-68757cd48d-n5gsn Jan 4 18:27:17.968: INFO: Creating log watcher for controller calico-system/calico-node-windows-chhhj, container calico-node-felix ... skipping 41 lines ... Jan 4 18:27:18.667: INFO: Creating log watcher for controller kube-system/etcd-capz-ukuy7t-control-plane-9rzvh, container etcd Jan 4 18:27:18.666: INFO: Creating log watcher for controller kube-system/coredns-56f4c55bf9-wcv7h, container coredns Jan 4 18:27:18.847: INFO: Fetching kube-system pod logs took 2.616048259s Jan 4 18:27:18.848: INFO: Dumping workload cluster default/capz-ukuy7t Azure activity log Jan 4 18:27:18.848: INFO: Creating log watcher for controller tigera-operator/tigera-operator-7795f5d79b-47rnv, container tigera-operator Jan 4 18:27:18.849: INFO: Collecting events for Pod tigera-operator/tigera-operator-7795f5d79b-47rnv Jan 4 18:27:28.757: INFO: Got error while iterating over activity logs for resource group capz-ukuy7t: insights.ActivityLogsClient#listNextResults: Failure responding to next results request: StatusCode=404 -- Original Error: autorest/azure: error response cannot be parsed: {"<!DOCTYPE html PUBLIC \"-//W3C//DTD XHTML 1.0 Strict//EN\" \"http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd\">\r\n<html xmlns=\"http://www.w3.org/1999/xhtml\">\r\n<head>\r\n<meta http-equiv=\"Content-Type\" content=\"text/html; charset=iso-8859-1\"/>\r\n<title>404 - File or directory not found.</title>\r\n<style type=\"text/css\">\r\n<!--\r\nbody{margin:0;font-size:.7em;font-family:Verdana, Arial, Helvetica, sans-serif;background:#EEEEEE;}\r\nfieldset{padding:0 15px 10px 15px;} \r\nh1{font-size:2.4em;margin:0;color:#FFF;}\r\nh2{font-si" '\x00' '\x00'} error: invalid character '<' looking for beginning of value Jan 4 18:27:28.757: INFO: Fetching activity logs took 9.909003115s ================ REDACTING LOGS ================ All sensitive variables are redacted cluster.cluster.x-k8s.io "capz-ukuy7t" deleted {"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:164","func":"k8s.io/test-infra/prow/entrypoint.Options.ExecuteProcess","level":"error","msg":"Process did not finish before 2h0m0s timeout","severity":"error","time":"2023-01-04T18:36:25Z"} ++ early_exit_handler ++ '[' -n 161 ']' ++ kill -TERM 161 ++ cleanup_dind ++ [[ true == \t\r\u\e ]] ++ echo 'Cleaning up after docker' ... skipping 13 lines ... ================================================================================ Cleaning up after docker Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running? Stopping Docker: dockerProgram process in pidfile '/var/run/docker-ssd.pid', 1 process(es), refused to die. ================================================================================ Done cleaning up after docker in docker. {"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:251","func":"k8s.io/test-infra/prow/entrypoint.gracefullyTerminate","level":"error","msg":"Process gracefully exited before 15m0s grace period","severity":"error","time":"2023-01-04T18:37:06Z"}