ci-kubernetes-e2e-azuredisk-capz-windows-2019 #1615750925840814080
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 2h15m |
| Revision | main |
... skipping 792 lines ... certificate.cert-manager.io "selfsigned-cert" deleted # Create secret for AzureClusterIdentity ./hack/create-identity-secret.sh make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' make[2]: Nothing to be done for 'kubectl'. make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' Error from server (NotFound): secrets "cluster-identity-secret" not found secret/cluster-identity-secret created secret/cluster-identity-secret labeled # Create customized cloud provider configs ./hack/create-custom-cloud-provider-config.sh make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' make[2]: Nothing to be done for 'kubectl'. ... skipping 221 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 197k 0 --:--:-- --:--:-- --:--:-- 197k 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.27.0-7134e0a6fda2d23be756abf24572f49470cd3283 || make container-all push-manifest Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.27.0-7134e0a6fda2d23be756abf24572f49470cd3283 not found: manifest unknown: manifest tagged by "v1.27.0-7134e0a6fda2d23be756abf24572f49470cd3283" 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.27.0-7134e0a6fda2d23be756abf24572f49470cd3283 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=7134e0a6fda2d23be756abf24572f49470cd3283 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-18T17:08: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 1784 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 222 lines ... Jan 18 17:22:21.441: INFO: PersistentVolumeClaim pvc-vgj8f found and phase=Bound (4.177480112s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:22:21.441[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:22:21.5[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:22:21.558[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 17:22:21.558[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:22:21.558[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 17:22:21.62[0m Jan 18 17:22:21.620: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fvrvj" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 18 17:22:21.678: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 58.174972ms Jan 18 17:22:23.739: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.118843876s Jan 18 17:22:25.738: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.117639956s Jan 18 17:22:27.736: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.116522218s Jan 18 17:22:29.737: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.117117745s Jan 18 17:22:31.737: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.117058121s ... skipping 385 lines ... Jan 18 17:35:23.744: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=true. Elapsed: 13m2.124306746s Jan 18 17:35:25.746: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=true. Elapsed: 13m4.126072426s Jan 18 17:35:27.746: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=false. Elapsed: 13m6.12580661s Jan 18 17:35:29.744: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=false. Elapsed: 13m8.123850463s Jan 18 17:35:31.745: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 13m10.125236416s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 17:35:31.745[0m Jan 18 17:35:31.745: INFO: Pod "azuredisk-volume-tester-fvrvj" satisfied condition "Succeeded or Failed" Jan 18 17:35:31.745: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-fvrvj" Jan 18 17:35:31.826: INFO: Pod azuredisk-volume-tester-fvrvj has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-fvrvj in namespace azuredisk-8081 [38;5;243m01/18/23 17:35:31.826[0m Jan 18 17:35:31.900: INFO: deleting PVC "azuredisk-8081"/"pvc-vgj8f" Jan 18 17:35:31.900: INFO: Deleting PersistentVolumeClaim "pvc-vgj8f" ... skipping 132 lines ... Jan 18 17:22:21.441: INFO: PersistentVolumeClaim pvc-vgj8f found and phase=Bound (4.177480112s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:22:21.441[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:22:21.5[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:22:21.558[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 17:22:21.558[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:22:21.558[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 17:22:21.62[0m Jan 18 17:22:21.620: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fvrvj" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 18 17:22:21.678: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 58.174972ms Jan 18 17:22:23.739: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.118843876s Jan 18 17:22:25.738: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.117639956s Jan 18 17:22:27.736: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.116522218s Jan 18 17:22:29.737: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.117117745s Jan 18 17:22:31.737: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.117058121s ... skipping 385 lines ... Jan 18 17:35:23.744: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=true. Elapsed: 13m2.124306746s Jan 18 17:35:25.746: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=true. Elapsed: 13m4.126072426s Jan 18 17:35:27.746: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=false. Elapsed: 13m6.12580661s Jan 18 17:35:29.744: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Running", Reason="", readiness=false. Elapsed: 13m8.123850463s Jan 18 17:35:31.745: INFO: Pod "azuredisk-volume-tester-fvrvj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 13m10.125236416s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 17:35:31.745[0m Jan 18 17:35:31.745: INFO: Pod "azuredisk-volume-tester-fvrvj" satisfied condition "Succeeded or Failed" Jan 18 17:35:31.745: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-fvrvj" Jan 18 17:35:31.826: INFO: Pod azuredisk-volume-tester-fvrvj has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-fvrvj in namespace azuredisk-8081 [38;5;243m01/18/23 17:35:31.826[0m Jan 18 17:35:31.900: INFO: deleting PVC "azuredisk-8081"/"pvc-vgj8f" Jan 18 17:35:31.900: INFO: Deleting PersistentVolumeClaim "pvc-vgj8f" ... skipping 106 lines ... Jan 18 17:42:05.276: INFO: PersistentVolumeClaim pvc-lk7lx found but phase is Pending instead of Bound. Jan 18 17:42:07.339: INFO: PersistentVolumeClaim pvc-lk7lx found and phase=Bound (4.186747147s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:42:07.339[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:42:07.401[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:42:07.463[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:42:07.463[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/18/23 17:42:07.529[0m Jan 18 17:42:07.529: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vdkr5" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 18 17:42:07.594: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 64.988349ms Jan 18 17:42:09.657: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.127181646s Jan 18 17:42:11.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.131184042s Jan 18 17:42:13.656: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.126793656s Jan 18 17:42:15.658: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.128120274s Jan 18 17:42:17.658: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.12890216s ... skipping 51 lines ... Jan 18 17:44:01.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=true. Elapsed: 1m54.132019245s Jan 18 17:44:03.660: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=false. Elapsed: 1m56.130715672s Jan 18 17:44:05.662: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=false. Elapsed: 1m58.132232245s Jan 18 17:44:07.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=false. Elapsed: 2m0.131058637s Jan 18 17:44:09.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m2.132020325s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 17:44:09.662[0m Jan 18 17:44:09.662: INFO: Pod "azuredisk-volume-tester-vdkr5" satisfied condition "Succeeded or Failed" Jan 18 17:44:09.662: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-vdkr5" Jan 18 17:44:09.741: INFO: Pod azuredisk-volume-tester-vdkr5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vdkr5 in namespace azuredisk-2540 [38;5;243m01/18/23 17:44:09.741[0m Jan 18 17:44:09.818: INFO: deleting PVC "azuredisk-2540"/"pvc-lk7lx" Jan 18 17:44:09.818: INFO: Deleting PersistentVolumeClaim "pvc-lk7lx" ... skipping 57 lines ... Jan 18 17:42:05.276: INFO: PersistentVolumeClaim pvc-lk7lx found but phase is Pending instead of Bound. Jan 18 17:42:07.339: INFO: PersistentVolumeClaim pvc-lk7lx found and phase=Bound (4.186747147s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:42:07.339[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:42:07.401[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:42:07.463[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:42:07.463[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/18/23 17:42:07.529[0m Jan 18 17:42:07.529: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vdkr5" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 18 17:42:07.594: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 64.988349ms Jan 18 17:42:09.657: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.127181646s Jan 18 17:42:11.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.131184042s Jan 18 17:42:13.656: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.126793656s Jan 18 17:42:15.658: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.128120274s Jan 18 17:42:17.658: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.12890216s ... skipping 51 lines ... Jan 18 17:44:01.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=true. Elapsed: 1m54.132019245s Jan 18 17:44:03.660: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=false. Elapsed: 1m56.130715672s Jan 18 17:44:05.662: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=false. Elapsed: 1m58.132232245s Jan 18 17:44:07.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Running", Reason="", readiness=false. Elapsed: 2m0.131058637s Jan 18 17:44:09.661: INFO: Pod "azuredisk-volume-tester-vdkr5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m2.132020325s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 17:44:09.662[0m Jan 18 17:44:09.662: INFO: Pod "azuredisk-volume-tester-vdkr5" satisfied condition "Succeeded or Failed" Jan 18 17:44:09.662: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-vdkr5" Jan 18 17:44:09.741: INFO: Pod azuredisk-volume-tester-vdkr5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vdkr5 in namespace azuredisk-2540 [38;5;243m01/18/23 17:44:09.741[0m Jan 18 17:44:09.818: INFO: deleting PVC "azuredisk-2540"/"pvc-lk7lx" Jan 18 17:44:09.818: INFO: Deleting PersistentVolumeClaim "pvc-lk7lx" ... skipping 57 lines ... Jan 18 17:46:32.062: INFO: PersistentVolumeClaim pvc-scctl found and phase=Bound (4.186557861s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:46:32.062[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:46:32.126[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:46:32.187[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 17:46:32.188[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:46:32.188[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 17:46:32.252[0m Jan 18 17:46:32.252: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gjrqr" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 18 17:46:32.314: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 61.674549ms Jan 18 17:46:34.377: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.124596815s Jan 18 17:46:36.376: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.124096088s Jan 18 17:46:38.377: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.124634053s Jan 18 17:46:40.378: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.125467949s Jan 18 17:46:42.377: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.124433523s ... skipping 26 lines ... Jan 18 17:47:36.382: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=true. Elapsed: 1m4.129782892s Jan 18 17:47:38.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=true. Elapsed: 1m6.127516757s Jan 18 17:47:40.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=false. Elapsed: 1m8.127416943s Jan 18 17:47:42.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.128119262s Jan 18 17:47:44.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m12.127753489s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 17:47:44.38[0m Jan 18 17:47:44.380: INFO: Pod "azuredisk-volume-tester-gjrqr" satisfied condition "Succeeded or Failed" Jan 18 17:47:44.380: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-gjrqr" Jan 18 17:47:44.458: INFO: Pod azuredisk-volume-tester-gjrqr has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-gjrqr in namespace azuredisk-4728 [38;5;243m01/18/23 17:47:44.458[0m Jan 18 17:47:44.530: INFO: deleting PVC "azuredisk-4728"/"pvc-scctl" Jan 18 17:47:44.530: INFO: Deleting PersistentVolumeClaim "pvc-scctl" ... skipping 58 lines ... Jan 18 17:46:32.062: INFO: PersistentVolumeClaim pvc-scctl found and phase=Bound (4.186557861s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:46:32.062[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:46:32.126[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:46:32.187[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 17:46:32.188[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:46:32.188[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 17:46:32.252[0m Jan 18 17:46:32.252: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gjrqr" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 18 17:46:32.314: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 61.674549ms Jan 18 17:46:34.377: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.124596815s Jan 18 17:46:36.376: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.124096088s Jan 18 17:46:38.377: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.124634053s Jan 18 17:46:40.378: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.125467949s Jan 18 17:46:42.377: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.124433523s ... skipping 26 lines ... Jan 18 17:47:36.382: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=true. Elapsed: 1m4.129782892s Jan 18 17:47:38.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=true. Elapsed: 1m6.127516757s Jan 18 17:47:40.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=false. Elapsed: 1m8.127416943s Jan 18 17:47:42.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.128119262s Jan 18 17:47:44.380: INFO: Pod "azuredisk-volume-tester-gjrqr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m12.127753489s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 17:47:44.38[0m Jan 18 17:47:44.380: INFO: Pod "azuredisk-volume-tester-gjrqr" satisfied condition "Succeeded or Failed" Jan 18 17:47:44.380: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-gjrqr" Jan 18 17:47:44.458: INFO: Pod azuredisk-volume-tester-gjrqr has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-gjrqr in namespace azuredisk-4728 [38;5;243m01/18/23 17:47:44.458[0m Jan 18 17:47:44.530: INFO: deleting PVC "azuredisk-4728"/"pvc-scctl" Jan 18 17:47:44.530: INFO: Deleting PersistentVolumeClaim "pvc-scctl" ... skipping 201 lines ... Jan 18 17:50:10.502: INFO: PersistentVolumeClaim pvc-l9p25 found and phase=Bound (4.186590858s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:50:10.502[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:50:10.564[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:50:10.626[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 17:50:10.626[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:50:10.626[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/18/23 17:50:10.691[0m Jan 18 17:50:10.691: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-v6stn" in namespace "azuredisk-1353" to be "Error status code" Jan 18 17:50:10.753: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 61.63731ms Jan 18 17:50:12.814: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.123501727s Jan 18 17:50:14.816: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.125451942s Jan 18 17:50:16.815: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.123994322s Jan 18 17:50:18.815: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.123587323s Jan 18 17:50:20.816: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.125316328s ... skipping 65 lines ... Jan 18 17:52:32.818: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=true. Elapsed: 2m22.127363047s Jan 18 17:52:34.819: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=true. Elapsed: 2m24.128042951s Jan 18 17:52:36.818: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=true. Elapsed: 2m26.127361202s Jan 18 17:52:38.819: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=false. Elapsed: 2m28.127757411s Jan 18 17:52:40.824: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=false. Elapsed: 2m30.133447274s Jan 18 17:52:42.819: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=false. Elapsed: 2m32.127771501s Jan 18 17:52:44.821: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Failed", Reason="", readiness=false. Elapsed: 2m34.129778546s [1mSTEP:[0m Saw pod failure [38;5;243m01/18/23 17:52:44.821[0m Jan 18 17:52:44.821: INFO: Pod "azuredisk-volume-tester-v6stn" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/18/23 17:52:44.821[0m Jan 18 17:52:44.903: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-v6stn" Jan 18 17:52:44.968: INFO: Pod azuredisk-volume-tester-v6stn 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 67 lines ... Jan 18 17:50:10.502: INFO: PersistentVolumeClaim pvc-l9p25 found and phase=Bound (4.186590858s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 17:50:10.502[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 17:50:10.564[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 17:50:10.626[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 17:50:10.626[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 17:50:10.626[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/18/23 17:50:10.691[0m Jan 18 17:50:10.691: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-v6stn" in namespace "azuredisk-1353" to be "Error status code" Jan 18 17:50:10.753: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 61.63731ms Jan 18 17:50:12.814: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.123501727s Jan 18 17:50:14.816: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.125451942s Jan 18 17:50:16.815: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.123994322s Jan 18 17:50:18.815: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.123587323s Jan 18 17:50:20.816: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.125316328s ... skipping 65 lines ... Jan 18 17:52:32.818: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=true. Elapsed: 2m22.127363047s Jan 18 17:52:34.819: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=true. Elapsed: 2m24.128042951s Jan 18 17:52:36.818: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=true. Elapsed: 2m26.127361202s Jan 18 17:52:38.819: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=false. Elapsed: 2m28.127757411s Jan 18 17:52:40.824: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=false. Elapsed: 2m30.133447274s Jan 18 17:52:42.819: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Running", Reason="", readiness=false. Elapsed: 2m32.127771501s Jan 18 17:52:44.821: INFO: Pod "azuredisk-volume-tester-v6stn": Phase="Failed", Reason="", readiness=false. Elapsed: 2m34.129778546s [1mSTEP:[0m Saw pod failure [38;5;243m01/18/23 17:52:44.821[0m Jan 18 17:52:44.821: INFO: Pod "azuredisk-volume-tester-v6stn" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/18/23 17:52:44.821[0m Jan 18 17:52:44.903: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-v6stn" Jan 18 17:52:44.968: INFO: Pod azuredisk-volume-tester-v6stn 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 595 lines ... Jan 18 18:03:43.568: 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, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hfg4g-54599bbc9f\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 18 18:03:45.568: 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, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hfg4g-54599bbc9f\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/18/23 18:03:47.699[0m [1mSTEP:[0m check pod exec [38;5;243m01/18/23 18:03:47.826[0m Jan 18 18:03:47.827: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-156 exec azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:03:48.610: INFO: rc: 1 Jan 18 18:03:48.610: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-156 exec azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k -- 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 18 18:03:50.611: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-156 exec azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:03:51.336: INFO: stderr: "" Jan 18 18:03:51.336: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/18/23 18:03:51.336[0m Jan 18 18:03:51.336: INFO: Deleting pod "azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k" in namespace "azuredisk-156" ... skipping 114 lines ... Jan 18 18:03:43.568: 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, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hfg4g-54599bbc9f\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 18 18:03:45.568: 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, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 18, 18, 2, 11, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hfg4g-54599bbc9f\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/18/23 18:03:47.699[0m [1mSTEP:[0m check pod exec [38;5;243m01/18/23 18:03:47.826[0m Jan 18 18:03:47.827: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-156 exec azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:03:48.610: INFO: rc: 1 Jan 18 18:03:48.610: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-156 exec azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k -- 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 18 18:03:50.611: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-156 exec azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:03:51.336: INFO: stderr: "" Jan 18 18:03:51.336: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/18/23 18:03:51.336[0m Jan 18 18:03:51.336: INFO: Deleting pod "azuredisk-volume-tester-hfg4g-54599bbc9f-9gn9k" in namespace "azuredisk-156" ... skipping 315 lines ... Jan 18 18:06:01.209: INFO: PersistentVolumeClaim pvc-s45cb found and phase=Bound (4.185810117s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:06:01.209[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:06:01.27[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:06:01.332[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 18:06:01.332[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:06:01.332[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:06:01.398[0m Jan 18 18:06:01.399: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cjhwr" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 18 18:06:01.464: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 65.23836ms Jan 18 18:06:03.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.131877234s Jan 18 18:06:05.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.131277175s Jan 18 18:06:07.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132910521s Jan 18 18:06:09.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.131091995s Jan 18 18:06:11.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.132672202s ... skipping 101 lines ... Jan 18 18:09:35.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=true. Elapsed: 3m34.132449633s Jan 18 18:09:37.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=false. Elapsed: 3m36.13187412s Jan 18 18:09:39.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=false. Elapsed: 3m38.13273282s Jan 18 18:09:41.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=false. Elapsed: 3m40.132396502s Jan 18 18:09:43.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 3m42.132039109s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:09:43.531[0m Jan 18 18:09:43.531: INFO: Pod "azuredisk-volume-tester-cjhwr" satisfied condition "Succeeded or Failed" Jan 18 18:09:43.531: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-cjhwr" Jan 18 18:09:43.613: INFO: Pod azuredisk-volume-tester-cjhwr has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-cjhwr in namespace azuredisk-1598 [38;5;243m01/18/23 18:09:43.613[0m ... skipping 131 lines ... Jan 18 18:06:01.209: INFO: PersistentVolumeClaim pvc-s45cb found and phase=Bound (4.185810117s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:06:01.209[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:06:01.27[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:06:01.332[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 18:06:01.332[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:06:01.332[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:06:01.398[0m Jan 18 18:06:01.399: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cjhwr" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 18 18:06:01.464: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 65.23836ms Jan 18 18:06:03.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.131877234s Jan 18 18:06:05.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.131277175s Jan 18 18:06:07.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.132910521s Jan 18 18:06:09.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.131091995s Jan 18 18:06:11.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.132672202s ... skipping 101 lines ... Jan 18 18:09:35.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=true. Elapsed: 3m34.132449633s Jan 18 18:09:37.530: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=false. Elapsed: 3m36.13187412s Jan 18 18:09:39.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=false. Elapsed: 3m38.13273282s Jan 18 18:09:41.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Running", Reason="", readiness=false. Elapsed: 3m40.132396502s Jan 18 18:09:43.531: INFO: Pod "azuredisk-volume-tester-cjhwr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 3m42.132039109s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:09:43.531[0m Jan 18 18:09:43.531: INFO: Pod "azuredisk-volume-tester-cjhwr" satisfied condition "Succeeded or Failed" Jan 18 18:09:43.531: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-cjhwr" Jan 18 18:09:43.613: INFO: Pod azuredisk-volume-tester-cjhwr has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-cjhwr in namespace azuredisk-1598 [38;5;243m01/18/23 18:09:43.613[0m ... skipping 139 lines ... Jan 18 18:14:32.190: INFO: PersistentVolumeClaim pvc-4gtjh found but phase is Pending instead of Bound. Jan 18 18:14:34.252: INFO: PersistentVolumeClaim pvc-4gtjh found and phase=Bound (4.185703479s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:14:34.252[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:14:34.313[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:14:34.375[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:14:34.375[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:14:34.442[0m Jan 18 18:14:34.442: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fkr95" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 18 18:14:34.504: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 61.391548ms Jan 18 18:14:36.566: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 2.123559219s Jan 18 18:14:38.565: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 4.123343378s Jan 18 18:14:40.566: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 6.124180777s Jan 18 18:14:42.565: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 8.123269676s Jan 18 18:14:44.566: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 10.12370827s ... skipping 42 lines ... Jan 18 18:16:10.571: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=true. Elapsed: 1m36.128703767s Jan 18 18:16:12.572: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=false. Elapsed: 1m38.129443992s Jan 18 18:16:14.570: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=false. Elapsed: 1m40.127757809s Jan 18 18:16:16.573: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=false. Elapsed: 1m42.13116807s Jan 18 18:16:18.573: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m44.131268501s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:16:18.573[0m Jan 18 18:16:18.574: INFO: Pod "azuredisk-volume-tester-fkr95" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/18/23 18:16:18.574[0m [1mSTEP:[0m Prow test resource group: capz-7gblvj [38;5;243m01/18/23 18:16:18.575[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-34218fbd-975c-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:16:18.575[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-34218fbd-975c-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:16:20.091[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/18/23 18:16:20.091[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/18/23 18:16:20.092[0m ... skipping 11 lines ... Jan 18 18:16:39.619: INFO: PersistentVolumeClaim pvc-9rwfw found and phase=Bound (4.188515161s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:16:39.619[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:16:39.681[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:16:39.748[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 18:16:39.748[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/18/23 18:16:39.748[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:16:39.813[0m Jan 18 18:16:39.814: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-7d8k6" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 18 18:16:39.875: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 61.383643ms Jan 18 18:16:41.938: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.124568142s Jan 18 18:16:43.939: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.125534503s Jan 18 18:16:45.939: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.125566939s Jan 18 18:16:47.938: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.124455954s Jan 18 18:16:49.938: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 10.124409169s ... skipping 67 lines ... Jan 18 18:19:05.942: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=true. Elapsed: 2m26.128827825s Jan 18 18:19:07.943: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=true. Elapsed: 2m28.12956069s Jan 18 18:19:09.942: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=false. Elapsed: 2m30.128946031s Jan 18 18:19:11.942: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=false. Elapsed: 2m32.128488697s Jan 18 18:19:13.941: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m34.127774999s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:19:13.941[0m Jan 18 18:19:13.941: INFO: Pod "azuredisk-volume-tester-7d8k6" satisfied condition "Succeeded or Failed" Jan 18 18:19:13.942: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-7d8k6" Jan 18 18:19:14.021: INFO: Pod azuredisk-volume-tester-7d8k6 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-7d8k6 in namespace azuredisk-8582 [38;5;243m01/18/23 18:19:14.021[0m Jan 18 18:19:14.151: INFO: deleting PVC "azuredisk-8582"/"pvc-9rwfw" Jan 18 18:19:14.151: INFO: Deleting PersistentVolumeClaim "pvc-9rwfw" ... skipping 60 lines ... Jan 18 18:14:32.190: INFO: PersistentVolumeClaim pvc-4gtjh found but phase is Pending instead of Bound. Jan 18 18:14:34.252: INFO: PersistentVolumeClaim pvc-4gtjh found and phase=Bound (4.185703479s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:14:34.252[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:14:34.313[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:14:34.375[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:14:34.375[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:14:34.442[0m Jan 18 18:14:34.442: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fkr95" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 18 18:14:34.504: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 61.391548ms Jan 18 18:14:36.566: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 2.123559219s Jan 18 18:14:38.565: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 4.123343378s Jan 18 18:14:40.566: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 6.124180777s Jan 18 18:14:42.565: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 8.123269676s Jan 18 18:14:44.566: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Pending", Reason="", readiness=false. Elapsed: 10.12370827s ... skipping 42 lines ... Jan 18 18:16:10.571: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=true. Elapsed: 1m36.128703767s Jan 18 18:16:12.572: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=false. Elapsed: 1m38.129443992s Jan 18 18:16:14.570: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=false. Elapsed: 1m40.127757809s Jan 18 18:16:16.573: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Running", Reason="", readiness=false. Elapsed: 1m42.13116807s Jan 18 18:16:18.573: INFO: Pod "azuredisk-volume-tester-fkr95": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m44.131268501s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:16:18.573[0m Jan 18 18:16:18.574: INFO: Pod "azuredisk-volume-tester-fkr95" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/18/23 18:16:18.574[0m [1mSTEP:[0m Prow test resource group: capz-7gblvj [38;5;243m01/18/23 18:16:18.575[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-34218fbd-975c-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:16:18.575[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-34218fbd-975c-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:16:20.091[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/18/23 18:16:20.091[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/18/23 18:16:20.092[0m ... skipping 11 lines ... Jan 18 18:16:39.619: INFO: PersistentVolumeClaim pvc-9rwfw found and phase=Bound (4.188515161s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:16:39.619[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:16:39.681[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:16:39.748[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 18:16:39.748[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/18/23 18:16:39.748[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:16:39.813[0m Jan 18 18:16:39.814: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-7d8k6" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 18 18:16:39.875: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 61.383643ms Jan 18 18:16:41.938: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.124568142s Jan 18 18:16:43.939: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.125534503s Jan 18 18:16:45.939: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.125566939s Jan 18 18:16:47.938: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.124455954s Jan 18 18:16:49.938: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Pending", Reason="", readiness=false. Elapsed: 10.124409169s ... skipping 67 lines ... Jan 18 18:19:05.942: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=true. Elapsed: 2m26.128827825s Jan 18 18:19:07.943: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=true. Elapsed: 2m28.12956069s Jan 18 18:19:09.942: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=false. Elapsed: 2m30.128946031s Jan 18 18:19:11.942: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Running", Reason="", readiness=false. Elapsed: 2m32.128488697s Jan 18 18:19:13.941: INFO: Pod "azuredisk-volume-tester-7d8k6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m34.127774999s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:19:13.941[0m Jan 18 18:19:13.941: INFO: Pod "azuredisk-volume-tester-7d8k6" satisfied condition "Succeeded or Failed" Jan 18 18:19:13.942: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-7d8k6" Jan 18 18:19:14.021: INFO: Pod azuredisk-volume-tester-7d8k6 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-7d8k6 in namespace azuredisk-8582 [38;5;243m01/18/23 18:19:14.021[0m Jan 18 18:19:14.151: INFO: deleting PVC "azuredisk-8582"/"pvc-9rwfw" Jan 18 18:19:14.151: INFO: Deleting PersistentVolumeClaim "pvc-9rwfw" ... skipping 59 lines ... Jan 18 18:21:56.211: INFO: PersistentVolumeClaim pvc-gh8j6 found but phase is Pending instead of Bound. Jan 18 18:21:58.273: INFO: PersistentVolumeClaim pvc-gh8j6 found and phase=Bound (4.185781215s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:21:58.273[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:21:58.334[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:21:58.396[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:21:58.396[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:21:58.461[0m Jan 18 18:21:58.461: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qkzpk" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 18 18:21:58.525: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 63.936857ms Jan 18 18:22:00.587: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.125864183s Jan 18 18:22:02.589: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.127574024s Jan 18 18:22:04.589: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.127061618s Jan 18 18:22:06.588: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.126523774s Jan 18 18:22:08.588: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.12644311s ... skipping 55 lines ... Jan 18 18:24:00.593: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=true. Elapsed: 2m2.131652583s Jan 18 18:24:02.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=false. Elapsed: 2m4.130601622s Jan 18 18:24:04.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=false. Elapsed: 2m6.130305363s Jan 18 18:24:06.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=false. Elapsed: 2m8.130904836s Jan 18 18:24:08.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m10.130284246s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:24:08.592[0m Jan 18 18:24:08.592: INFO: Pod "azuredisk-volume-tester-qkzpk" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/18/23 18:24:08.592[0m [1mSTEP:[0m Prow test resource group: capz-7gblvj [38;5;243m01/18/23 18:24:08.593[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-4c489f4c-975d-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:24:08.593[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-4c489f4c-975d-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:24:10.065[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/18/23 18:24:10.065[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/18/23 18:24:10.065[0m ... skipping 27 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:24:49.774[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:24:49.836[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:24:49.897[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 18:24:49.897[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/18/23 18:24:49.897[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/18/23 18:24:49.898[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:24:49.966[0m Jan 18 18:24:49.966: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cg8gm" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 18 18:24:50.027: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 61.257759ms Jan 18 18:24:52.089: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.123133465s Jan 18 18:24:54.090: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.123983698s Jan 18 18:24:56.090: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.123963173s Jan 18 18:24:58.090: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.12429476s Jan 18 18:25:00.089: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 10.123062163s ... skipping 110 lines ... Jan 18 18:28:42.093: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=true. Elapsed: 3m52.126835899s Jan 18 18:28:44.093: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=true. Elapsed: 3m54.127630348s Jan 18 18:28:46.095: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=true. Elapsed: 3m56.129066785s Jan 18 18:28:48.093: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=false. Elapsed: 3m58.127361908s Jan 18 18:28:50.094: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4m0.128472617s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:28:50.094[0m Jan 18 18:28:50.095: INFO: Pod "azuredisk-volume-tester-cg8gm" satisfied condition "Succeeded or Failed" Jan 18 18:28:50.095: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-cg8gm" Jan 18 18:28:50.181: INFO: Pod azuredisk-volume-tester-cg8gm has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-cg8gm in namespace azuredisk-7726 [38;5;243m01/18/23 18:28:50.181[0m Jan 18 18:28:50.254: INFO: deleting PVC "azuredisk-7726"/"pvc-z7mk4" Jan 18 18:28:50.254: INFO: Deleting PersistentVolumeClaim "pvc-z7mk4" ... skipping 82 lines ... Jan 18 18:21:56.211: INFO: PersistentVolumeClaim pvc-gh8j6 found but phase is Pending instead of Bound. Jan 18 18:21:58.273: INFO: PersistentVolumeClaim pvc-gh8j6 found and phase=Bound (4.185781215s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:21:58.273[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:21:58.334[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:21:58.396[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:21:58.396[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:21:58.461[0m Jan 18 18:21:58.461: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qkzpk" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 18 18:21:58.525: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 63.936857ms Jan 18 18:22:00.587: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.125864183s Jan 18 18:22:02.589: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.127574024s Jan 18 18:22:04.589: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.127061618s Jan 18 18:22:06.588: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.126523774s Jan 18 18:22:08.588: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.12644311s ... skipping 55 lines ... Jan 18 18:24:00.593: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=true. Elapsed: 2m2.131652583s Jan 18 18:24:02.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=false. Elapsed: 2m4.130601622s Jan 18 18:24:04.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=false. Elapsed: 2m6.130305363s Jan 18 18:24:06.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Running", Reason="", readiness=false. Elapsed: 2m8.130904836s Jan 18 18:24:08.592: INFO: Pod "azuredisk-volume-tester-qkzpk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2m10.130284246s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:24:08.592[0m Jan 18 18:24:08.592: INFO: Pod "azuredisk-volume-tester-qkzpk" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/18/23 18:24:08.592[0m [1mSTEP:[0m Prow test resource group: capz-7gblvj [38;5;243m01/18/23 18:24:08.593[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-4c489f4c-975d-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:24:08.593[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-4c489f4c-975d-11ed-956f-3e60229987cd [38;5;243m01/18/23 18:24:10.065[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/18/23 18:24:10.065[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/18/23 18:24:10.065[0m ... skipping 27 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:24:49.774[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:24:49.836[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:24:49.897[0m [1mSTEP:[0m setting up the pod [38;5;243m01/18/23 18:24:49.897[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/18/23 18:24:49.897[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/18/23 18:24:49.898[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:24:49.966[0m Jan 18 18:24:49.966: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cg8gm" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 18 18:24:50.027: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 61.257759ms Jan 18 18:24:52.089: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.123133465s Jan 18 18:24:54.090: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.123983698s Jan 18 18:24:56.090: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.123963173s Jan 18 18:24:58.090: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.12429476s Jan 18 18:25:00.089: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Pending", Reason="", readiness=false. Elapsed: 10.123062163s ... skipping 110 lines ... Jan 18 18:28:42.093: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=true. Elapsed: 3m52.126835899s Jan 18 18:28:44.093: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=true. Elapsed: 3m54.127630348s Jan 18 18:28:46.095: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=true. Elapsed: 3m56.129066785s Jan 18 18:28:48.093: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Running", Reason="", readiness=false. Elapsed: 3m58.127361908s Jan 18 18:28:50.094: INFO: Pod "azuredisk-volume-tester-cg8gm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4m0.128472617s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:28:50.094[0m Jan 18 18:28:50.095: INFO: Pod "azuredisk-volume-tester-cg8gm" satisfied condition "Succeeded or Failed" Jan 18 18:28:50.095: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-cg8gm" Jan 18 18:28:50.181: INFO: Pod azuredisk-volume-tester-cg8gm has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-cg8gm in namespace azuredisk-7726 [38;5;243m01/18/23 18:28:50.181[0m Jan 18 18:28:50.254: INFO: deleting PVC "azuredisk-7726"/"pvc-z7mk4" Jan 18 18:28:50.254: INFO: Deleting PersistentVolumeClaim "pvc-z7mk4" ... skipping 105 lines ... Jan 18 18:33:17.799: INFO: PersistentVolumeClaim pvc-z887p found but phase is Pending instead of Bound. Jan 18 18:33:19.861: INFO: PersistentVolumeClaim pvc-z887p found and phase=Bound (4.186975067s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:33:19.861[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:33:19.923[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:33:19.985[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:33:19.985[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:33:20.051[0m Jan 18 18:33:20.051: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-llt4f" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 18 18:33:20.120: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 69.074449ms Jan 18 18:33:22.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135819017s Jan 18 18:33:24.188: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.136686879s Jan 18 18:33:26.186: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.134746663s Jan 18 18:33:28.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.135781681s Jan 18 18:33:30.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.13646049s ... skipping 80 lines ... Jan 18 18:36:12.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=true. Elapsed: 2m52.135941168s Jan 18 18:36:14.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=false. Elapsed: 2m54.136029615s Jan 18 18:36:16.188: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=false. Elapsed: 2m56.136722308s Jan 18 18:36:18.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=false. Elapsed: 2m58.135812495s Jan 18 18:36:20.186: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 3m0.134778416s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:36:20.186[0m Jan 18 18:36:20.186: INFO: Pod "azuredisk-volume-tester-llt4f" satisfied condition "Succeeded or Failed" Jan 18 18:36:20.186: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-llt4f" Jan 18 18:36:20.272: INFO: Pod azuredisk-volume-tester-llt4f has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-llt4f in namespace azuredisk-3086 [38;5;243m01/18/23 18:36:20.272[0m Jan 18 18:36:20.350: INFO: deleting PVC "azuredisk-3086"/"pvc-z887p" Jan 18 18:36:20.350: INFO: Deleting PersistentVolumeClaim "pvc-z887p" ... skipping 113 lines ... Jan 18 18:33:17.799: INFO: PersistentVolumeClaim pvc-z887p found but phase is Pending instead of Bound. Jan 18 18:33:19.861: INFO: PersistentVolumeClaim pvc-z887p found and phase=Bound (4.186975067s) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:33:19.861[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:33:19.923[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:33:19.985[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:33:19.985[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/18/23 18:33:20.051[0m Jan 18 18:33:20.051: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-llt4f" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 18 18:33:20.120: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 69.074449ms Jan 18 18:33:22.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135819017s Jan 18 18:33:24.188: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.136686879s Jan 18 18:33:26.186: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.134746663s Jan 18 18:33:28.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.135781681s Jan 18 18:33:30.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.13646049s ... skipping 80 lines ... Jan 18 18:36:12.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=true. Elapsed: 2m52.135941168s Jan 18 18:36:14.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=false. Elapsed: 2m54.136029615s Jan 18 18:36:16.188: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=false. Elapsed: 2m56.136722308s Jan 18 18:36:18.187: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Running", Reason="", readiness=false. Elapsed: 2m58.135812495s Jan 18 18:36:20.186: INFO: Pod "azuredisk-volume-tester-llt4f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 3m0.134778416s [1mSTEP:[0m Saw pod success [38;5;243m01/18/23 18:36:20.186[0m Jan 18 18:36:20.186: INFO: Pod "azuredisk-volume-tester-llt4f" satisfied condition "Succeeded or Failed" Jan 18 18:36:20.186: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-llt4f" Jan 18 18:36:20.272: INFO: Pod azuredisk-volume-tester-llt4f has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-llt4f in namespace azuredisk-3086 [38;5;243m01/18/23 18:36:20.272[0m Jan 18 18:36:20.350: INFO: deleting PVC "azuredisk-3086"/"pvc-z887p" Jan 18 18:36:20.350: INFO: Deleting PersistentVolumeClaim "pvc-z887p" ... skipping 97 lines ... I0118 18:40:22.064354 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:40:24.062853 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:40:26.066461 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:40:28.063433 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:40:30.063578 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:40:32.063768 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready {"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-18T18:40:33Z"} ++ early_exit_handler ++ '[' -n 161 ']' ++ kill -TERM 161 ++ cleanup_dind ++ [[ true == \t\r\u\e ]] ++ echo 'Cleaning up after docker' ... skipping 387 lines ... Jan 18 18:47:10.178: INFO: deleting PVC "azuredisk-4801"/"pvc-pbrrm" Jan 18 18:47:10.178: INFO: Deleting PersistentVolumeClaim "pvc-pbrrm" [1mSTEP:[0m waiting for claim's PV "pvc-3c843c55-0008-4dc4-8dc7-162a07da419a" to be deleted [38;5;243m01/18/23 18:47:10.241[0m Jan 18 18:47:10.241: INFO: Waiting up to 10m0s for PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a to get deleted Jan 18 18:47:10.299: INFO: PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a found and phase=Bound (58.394205ms) Jan 18 18:47:15.359: INFO: PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a found and phase=Bound (5.117776843s) panic: Failed to get controller-runtime client Unexpected error: <*url.Error | 0xc00059d950>: { Op: "Get", URL: "https://127.0.0.1:43103/api?timeout=32s", Err: <*net.OpError | 0xc0005310e0>{ Op: "dial", Net: "tcp", Source: nil, ... skipping 9 lines ... }, } Get "https://127.0.0.1:43103/api?timeout=32s": dial tcp 127.0.0.1:43103: connect: connection refused occurred goroutine 1 [running]: main.Fail({0xc00082c600?, 0xc000680720?}, {0xc00059d950?, 0xc00082c300?, 0x1debe1a?}) /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/test/logger.go:36 +0x2d github.com/onsi/gomega/internal.(*Assertion).match(0xc000a904c0, {0x3319db8, 0x46e0de8}, 0x0, {0xc00003a180, 0x1, 0x1}) /home/prow/go/pkg/mod/github.com/onsi/gomega@v1.24.2/internal/assertion.go:106 +0x1f0 github.com/onsi/gomega/internal.(*Assertion).ToNot(0xc000a904c0, {0x3319db8, 0x46e0de8}, {0xc00003a180, 0x1, 0x1}) /home/prow/go/pkg/mod/github.com/onsi/gomega@v1.24.2/internal/assertion.go:68 +0xb2 sigs.k8s.io/cluster-api/test/framework.(*clusterProxy).GetClient(0xc0002f5600) ... skipping 5 lines ... exit status 2 ================ REDACTING LOGS ================ All sensitive variables are redacted The connection to the server 127.0.0.1:43103 was refused - did you specify the right host or port? /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kind-v0.17.0 delete cluster --name=capz || true Deleting cluster "capz" ... ERROR: failed to delete cluster "capz": error listing nodes: failed to list nodes: command "docker ps -a --filter label=io.x-k8s.kind.cluster=capz --format '{{.Names}}'" failed with error: exit status 1 Command Output: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running? /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kind-v0.17.0 delete cluster --name=capz-e2e || true Deleting cluster "capz-e2e" ... ERROR: failed to delete cluster "capz-e2e": error listing nodes: failed to list nodes: command "docker ps -a --filter label=io.x-k8s.kind.cluster=capz-e2e --format '{{.Names}}'" failed with error: exit status 1 Command Output: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running? Jan 18 18:47:20.418: INFO: PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a found and phase=Released (10.17744942s) Jan 18 18:47:25.481: INFO: PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a found and phase=Released (15.240571642s) Jan 18 18:47:30.545: INFO: PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a found and phase=Released (20.304367792s) Jan 18 18:47:35.608: INFO: PersistentVolume pvc-3c843c55-0008-4dc4-8dc7-162a07da419a found and phase=Released (25.367212952s) ... skipping 367 lines ... I0118 18:52:31.806934 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:52:33.807118 41794 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/18/23 18:52:33.869[0m [1mSTEP:[0m check pod exec [38;5;243m01/18/23 18:52:33.932[0m Jan 18 18:52:33.933: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1166 exec azuredisk-volume-tester-vb86d-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:52:34.659: INFO: rc: 1 Jan 18 18:52:34.659: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-vb86d-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1166 exec azuredisk-volume-tester-vb86d-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 18 18:52:36.660: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1166 exec azuredisk-volume-tester-vb86d-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:52:37.380: INFO: stderr: "" Jan 18 18:52:37.380: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/18/23 18:52:37.38[0m Jan 18 18:52:37.380: INFO: Deleting pod "azuredisk-volume-tester-vb86d-0" in namespace "azuredisk-1166" ... skipping 131 lines ... I0118 18:52:31.806934 41794 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0118 18:52:33.807118 41794 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/18/23 18:52:33.869[0m [1mSTEP:[0m check pod exec [38;5;243m01/18/23 18:52:33.932[0m Jan 18 18:52:33.933: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1166 exec azuredisk-volume-tester-vb86d-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:52:34.659: INFO: rc: 1 Jan 18 18:52:34.659: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-vb86d-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1166 exec azuredisk-volume-tester-vb86d-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 18 18:52:36.660: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1166 exec azuredisk-volume-tester-vb86d-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 18 18:52:37.380: INFO: stderr: "" Jan 18 18:52:37.380: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/18/23 18:52:37.38[0m Jan 18 18:52:37.380: INFO: Deleting pod "azuredisk-volume-tester-vb86d-0" in namespace "azuredisk-1166" ... skipping 225 lines ... Jan 18 18:55:15.768: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-zdpqh] to have phase Bound Jan 18 18:55:15.829: INFO: PersistentVolumeClaim pvc-zdpqh found and phase=Bound (60.914285ms) [1mSTEP:[0m checking the PVC [38;5;243m01/18/23 18:55:15.829[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/18/23 18:55:15.889[0m [1mSTEP:[0m checking the PV [38;5;243m01/18/23 18:55:15.947[0m [1mSTEP:[0m deploying the pod [38;5;243m01/18/23 18:55:15.948[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/18/23 18:55:16.012[0m Jan 18 18:55:16.012: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gqtw2" in namespace "azuredisk-5399" to be "Error status code" Jan 18 18:55:16.071: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 59.043762ms Jan 18 18:55:18.134: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 2.121394981s Jan 18 18:55:20.131: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 4.118749154s Jan 18 18:55:22.131: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 6.118480594s Jan 18 18:55:24.133: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 8.120514819s Jan 18 18:55:26.130: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 10.118318027s Jan 18 18:55:28.130: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 12.118350976s Jan 18 18:55:30.132: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 14.119723743s Jan 18 18:55:32.131: INFO: Pod "azuredisk-volume-tester-gqtw2": Phase="Pending", Reason="", readiness=false. Elapsed: 16.118766765s {"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:254","func":"k8s.io/test-infra/prow/entrypoint.gracefullyTerminate","level":"error","msg":"Process did not exit before 15m0s grace period","severity":"error","time":"2023-01-18T18:55:33Z"} {"component":"entrypoint","error":"os: process already finished","file":"k8s.io/test-infra/prow/entrypoint/run.go:256","func":"k8s.io/test-infra/prow/entrypoint.gracefullyTerminate","level":"error","msg":"Could not kill process after grace period","severity":"error","time":"2023-01-18T18:55:33Z"}