kubernetes-sigs/azuredisk-csi-driver PR #1665 pull-azuredisk-csi-driver-e2e-capz-windows-2019 #1610461002673950720
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | umagnus: cleanup: Use k8s utils pointer instead of Azure autorest/to |
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 2h0m |
| Revision | bad2a3e7841488d79cd6b6eda2616603ec33a224 |
| Refs |
1665 |
... skipping 765 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 137 lines ... # Wait for the kubeconfig to become available. timeout --foreground 300 bash -c "while ! /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kubectl-v1.22.4 get secrets | grep capz-00jd55-kubeconfig; do sleep 1; done" capz-00jd55-kubeconfig cluster.x-k8s.io/secret 1 1s # Get kubeconfig and store it locally. /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kubectl-v1.22.4 get secrets capz-00jd55-kubeconfig -o json | jq -r .data.value | base64 --decode > ./kubeconfig timeout --foreground 600 bash -c "while ! /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kubectl-v1.22.4 --kubeconfig=./kubeconfig get nodes | grep control-plane; do sleep 1; done" error: the server doesn't have a resource type "nodes" capz-00jd55-control-plane-2fg4f NotReady control-plane,master 7s v1.23.16-rc.0.37+548d5d2298c4a5 run "/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kubectl-v1.22.4 --kubeconfig=./kubeconfig ..." to work with the new target cluster make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure' CCM cluster CIDR: 192.168.0.0/16 Waiting for 1 control plane machine(s), 0 worker machine(s), and 2 windows machine(s) to become Ready node/capz-00jd-5nnsv condition met ... skipping 40 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 175k 0 --:--:-- --:--:-- --:--:-- 175k 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-c5139edbb80a8677f61bd420ac1b58e4aac70a31 || make container-all push-manifest Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31 not found: manifest unknown: manifest tagged by "v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31" 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-c5139edbb80a8677f61bd420ac1b58e4aac70a31 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=c5139edbb80a8677f61bd420ac1b58e4aac70a31 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-04T02:43:30Z -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 1806 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 4 02:56:42.777: INFO: PersistentVolumeClaim pvc-4lp4h found and phase=Bound (4.312701119s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 02:56:42.777[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 02:56:42.883[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 02:56:42.987[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 02:56:42.987[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 02:56:42.988[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 02:56:43.099[0m Jan 4 02:56:43.100: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-97vq8" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 4 02:56:43.205: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 105.029379ms Jan 4 02:56:45.311: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210334538s Jan 4 02:56:47.310: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209978267s Jan 4 02:56:49.313: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.212872088s Jan 4 02:56:51.315: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.214480034s Jan 4 02:56:53.310: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209993197s ... skipping 204 lines ... Jan 4 03:03:43.318: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=true. Elapsed: 7m0.218225269s Jan 4 03:03:45.317: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=true. Elapsed: 7m2.216631315s Jan 4 03:03:47.317: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=true. Elapsed: 7m4.216580913s Jan 4 03:03:49.318: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=false. Elapsed: 7m6.217428041s Jan 4 03:03:51.317: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 7m8.217093087s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:03:51.317[0m Jan 4 03:03:51.318: INFO: Pod "azuredisk-volume-tester-97vq8" satisfied condition "Succeeded or Failed" Jan 4 03:03:51.318: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-97vq8" Jan 4 03:03:51.449: INFO: Pod azuredisk-volume-tester-97vq8 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-97vq8 in namespace azuredisk-8081 [38;5;243m01/04/23 03:03:51.449[0m Jan 4 03:03:51.580: INFO: deleting PVC "azuredisk-8081"/"pvc-4lp4h" Jan 4 03:03:51.580: INFO: Deleting PersistentVolumeClaim "pvc-4lp4h" ... skipping 50 lines ... Jan 4 02:56:42.777: INFO: PersistentVolumeClaim pvc-4lp4h found and phase=Bound (4.312701119s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 02:56:42.777[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 02:56:42.883[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 02:56:42.987[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 02:56:42.987[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 02:56:42.988[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 02:56:43.099[0m Jan 4 02:56:43.100: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-97vq8" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 4 02:56:43.205: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 105.029379ms Jan 4 02:56:45.311: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210334538s Jan 4 02:56:47.310: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209978267s Jan 4 02:56:49.313: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.212872088s Jan 4 02:56:51.315: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.214480034s Jan 4 02:56:53.310: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209993197s ... skipping 204 lines ... Jan 4 03:03:43.318: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=true. Elapsed: 7m0.218225269s Jan 4 03:03:45.317: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=true. Elapsed: 7m2.216631315s Jan 4 03:03:47.317: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=true. Elapsed: 7m4.216580913s Jan 4 03:03:49.318: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Running", Reason="", readiness=false. Elapsed: 7m6.217428041s Jan 4 03:03:51.317: INFO: Pod "azuredisk-volume-tester-97vq8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 7m8.217093087s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:03:51.317[0m Jan 4 03:03:51.318: INFO: Pod "azuredisk-volume-tester-97vq8" satisfied condition "Succeeded or Failed" Jan 4 03:03:51.318: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-97vq8" Jan 4 03:03:51.449: INFO: Pod azuredisk-volume-tester-97vq8 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-97vq8 in namespace azuredisk-8081 [38;5;243m01/04/23 03:03:51.449[0m Jan 4 03:03:51.580: INFO: deleting PVC "azuredisk-8081"/"pvc-4lp4h" Jan 4 03:03:51.580: INFO: Deleting PersistentVolumeClaim "pvc-4lp4h" ... skipping 37 lines ... Jan 4 03:04:36.795: INFO: PersistentVolumeClaim pvc-pnvp5 found but phase is Pending instead of Bound. Jan 4 03:04:38.900: INFO: PersistentVolumeClaim pvc-pnvp5 found and phase=Bound (4.312078049s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:04:38.9[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:04:39.003[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:04:39.107[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:04:39.107[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/04/23 03:04:39.217[0m Jan 4 03:04:39.218: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vtkv5" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 4 03:04:39.320: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 102.762294ms Jan 4 03:04:41.425: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207402871s Jan 4 03:04:43.426: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208338175s Jan 4 03:04:45.425: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207223236s Jan 4 03:04:47.425: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207707004s Jan 4 03:04:49.426: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208301977s ... skipping 20 lines ... Jan 4 03:05:31.434: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=true. Elapsed: 52.21616766s Jan 4 03:05:33.433: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=false. Elapsed: 54.214894801s Jan 4 03:05:35.433: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=false. Elapsed: 56.215210275s Jan 4 03:05:37.432: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=false. Elapsed: 58.214415561s Jan 4 03:05:39.436: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.218761984s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:05:39.436[0m Jan 4 03:05:39.437: INFO: Pod "azuredisk-volume-tester-vtkv5" satisfied condition "Succeeded or Failed" Jan 4 03:05:39.437: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-vtkv5" Jan 4 03:05:39.566: INFO: Pod azuredisk-volume-tester-vtkv5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vtkv5 in namespace azuredisk-2540 [38;5;243m01/04/23 03:05:39.566[0m Jan 4 03:05:39.714: INFO: deleting PVC "azuredisk-2540"/"pvc-pnvp5" Jan 4 03:05:39.714: INFO: Deleting PersistentVolumeClaim "pvc-pnvp5" ... skipping 38 lines ... Jan 4 03:04:36.795: INFO: PersistentVolumeClaim pvc-pnvp5 found but phase is Pending instead of Bound. Jan 4 03:04:38.900: INFO: PersistentVolumeClaim pvc-pnvp5 found and phase=Bound (4.312078049s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:04:38.9[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:04:39.003[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:04:39.107[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:04:39.107[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/04/23 03:04:39.217[0m Jan 4 03:04:39.218: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vtkv5" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 4 03:04:39.320: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 102.762294ms Jan 4 03:04:41.425: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207402871s Jan 4 03:04:43.426: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208338175s Jan 4 03:04:45.425: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207223236s Jan 4 03:04:47.425: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207707004s Jan 4 03:04:49.426: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208301977s ... skipping 20 lines ... Jan 4 03:05:31.434: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=true. Elapsed: 52.21616766s Jan 4 03:05:33.433: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=false. Elapsed: 54.214894801s Jan 4 03:05:35.433: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=false. Elapsed: 56.215210275s Jan 4 03:05:37.432: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Running", Reason="", readiness=false. Elapsed: 58.214415561s Jan 4 03:05:39.436: INFO: Pod "azuredisk-volume-tester-vtkv5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.218761984s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:05:39.436[0m Jan 4 03:05:39.437: INFO: Pod "azuredisk-volume-tester-vtkv5" satisfied condition "Succeeded or Failed" Jan 4 03:05:39.437: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-vtkv5" Jan 4 03:05:39.566: INFO: Pod azuredisk-volume-tester-vtkv5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vtkv5 in namespace azuredisk-2540 [38;5;243m01/04/23 03:05:39.566[0m Jan 4 03:05:39.714: INFO: deleting PVC "azuredisk-2540"/"pvc-pnvp5" Jan 4 03:05:39.714: INFO: Deleting PersistentVolumeClaim "pvc-pnvp5" ... skipping 38 lines ... Jan 4 03:06:27.024: INFO: PersistentVolumeClaim pvc-qkhwj found and phase=Bound (4.312570233s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:06:27.024[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:06:27.127[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:06:27.231[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:06:27.232[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:06:27.232[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:06:27.344[0m Jan 4 03:06:27.345: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-2wr8f" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 4 03:06:27.451: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 106.074433ms Jan 4 03:06:29.558: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.213183662s Jan 4 03:06:31.556: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210903044s Jan 4 03:06:33.556: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.211210773s Jan 4 03:06:35.561: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.216810299s Jan 4 03:06:37.554: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209588452s ... skipping 17 lines ... Jan 4 03:07:13.567: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=true. Elapsed: 46.222062255s Jan 4 03:07:15.563: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=true. Elapsed: 48.218689881s Jan 4 03:07:17.563: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=false. Elapsed: 50.21820651s Jan 4 03:07:19.564: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=false. Elapsed: 52.219601902s Jan 4 03:07:21.562: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 54.216995466s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:07:21.562[0m Jan 4 03:07:21.562: INFO: Pod "azuredisk-volume-tester-2wr8f" satisfied condition "Succeeded or Failed" Jan 4 03:07:21.562: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-2wr8f" Jan 4 03:07:21.686: INFO: Pod azuredisk-volume-tester-2wr8f has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-2wr8f in namespace azuredisk-4728 [38;5;243m01/04/23 03:07:21.686[0m Jan 4 03:07:21.819: INFO: deleting PVC "azuredisk-4728"/"pvc-qkhwj" Jan 4 03:07:21.819: INFO: Deleting PersistentVolumeClaim "pvc-qkhwj" ... skipping 39 lines ... Jan 4 03:06:27.024: INFO: PersistentVolumeClaim pvc-qkhwj found and phase=Bound (4.312570233s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:06:27.024[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:06:27.127[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:06:27.231[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:06:27.232[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:06:27.232[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:06:27.344[0m Jan 4 03:06:27.345: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-2wr8f" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 4 03:06:27.451: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 106.074433ms Jan 4 03:06:29.558: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.213183662s Jan 4 03:06:31.556: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210903044s Jan 4 03:06:33.556: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.211210773s Jan 4 03:06:35.561: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.216810299s Jan 4 03:06:37.554: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209588452s ... skipping 17 lines ... Jan 4 03:07:13.567: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=true. Elapsed: 46.222062255s Jan 4 03:07:15.563: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=true. Elapsed: 48.218689881s Jan 4 03:07:17.563: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=false. Elapsed: 50.21820651s Jan 4 03:07:19.564: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Running", Reason="", readiness=false. Elapsed: 52.219601902s Jan 4 03:07:21.562: INFO: Pod "azuredisk-volume-tester-2wr8f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 54.216995466s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:07:21.562[0m Jan 4 03:07:21.562: INFO: Pod "azuredisk-volume-tester-2wr8f" satisfied condition "Succeeded or Failed" Jan 4 03:07:21.562: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-2wr8f" Jan 4 03:07:21.686: INFO: Pod azuredisk-volume-tester-2wr8f has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-2wr8f in namespace azuredisk-4728 [38;5;243m01/04/23 03:07:21.686[0m Jan 4 03:07:21.819: INFO: deleting PVC "azuredisk-4728"/"pvc-qkhwj" Jan 4 03:07:21.819: INFO: Deleting PersistentVolumeClaim "pvc-qkhwj" ... skipping 182 lines ... Jan 4 03:08:15.587: INFO: PersistentVolumeClaim pvc-8r785 found and phase=Bound (4.316803431s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:08:15.587[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:08:15.691[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:08:15.796[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:08:15.796[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:08:15.796[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 03:08:15.914[0m Jan 4 03:08:15.914: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qzhdx" in namespace "azuredisk-1353" to be "Error status code" Jan 4 03:08:16.019: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 105.21684ms Jan 4 03:08:18.125: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.211113499s Jan 4 03:08:20.124: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21025665s Jan 4 03:08:22.125: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.211092977s Jan 4 03:08:24.125: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.211072577s Jan 4 03:08:26.124: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209802131s ... skipping 18 lines ... Jan 4 03:09:04.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 48.217790567s Jan 4 03:09:06.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 50.218476004s Jan 4 03:09:08.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 52.21764151s Jan 4 03:09:10.131: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 54.217133943s Jan 4 03:09:12.131: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=false. Elapsed: 56.217056957s Jan 4 03:09:14.134: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=false. Elapsed: 58.219971749s Jan 4 03:09:16.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Failed", Reason="", readiness=false. Elapsed: 1m0.217536637s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 03:09:16.132[0m Jan 4 03:09:16.132: INFO: Pod "azuredisk-volume-tester-qzhdx" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 03:09:16.132[0m Jan 4 03:09:16.262: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-qzhdx" Jan 4 03:09:16.370: INFO: Pod azuredisk-volume-tester-qzhdx 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 48 lines ... Jan 4 03:08:15.587: INFO: PersistentVolumeClaim pvc-8r785 found and phase=Bound (4.316803431s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:08:15.587[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:08:15.691[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:08:15.796[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:08:15.796[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:08:15.796[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 03:08:15.914[0m Jan 4 03:08:15.914: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qzhdx" in namespace "azuredisk-1353" to be "Error status code" Jan 4 03:08:16.019: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 105.21684ms Jan 4 03:08:18.125: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.211113499s Jan 4 03:08:20.124: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21025665s Jan 4 03:08:22.125: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.211092977s Jan 4 03:08:24.125: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.211072577s Jan 4 03:08:26.124: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209802131s ... skipping 18 lines ... Jan 4 03:09:04.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 48.217790567s Jan 4 03:09:06.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 50.218476004s Jan 4 03:09:08.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 52.21764151s Jan 4 03:09:10.131: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=true. Elapsed: 54.217133943s Jan 4 03:09:12.131: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=false. Elapsed: 56.217056957s Jan 4 03:09:14.134: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Running", Reason="", readiness=false. Elapsed: 58.219971749s Jan 4 03:09:16.132: INFO: Pod "azuredisk-volume-tester-qzhdx": Phase="Failed", Reason="", readiness=false. Elapsed: 1m0.217536637s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 03:09:16.132[0m Jan 4 03:09:16.132: INFO: Pod "azuredisk-volume-tester-qzhdx" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 03:09:16.132[0m Jan 4 03:09:16.262: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-qzhdx" Jan 4 03:09:16.370: INFO: Pod azuredisk-volume-tester-qzhdx 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 463 lines ... Jan 4 03:15:27.944: 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hrxgj-6996f94dd5\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 4 03:15:29.943: 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hrxgj-6996f94dd5\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 03:15:32.16[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 03:15:32.375[0m Jan 4 03:15:32.375: 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-hrxgj-6996f94dd5-btnqk -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:15:33.580: INFO: rc: 1 Jan 4 03:15:33.580: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-hrxgj-6996f94dd5-btnqk": 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-hrxgj-6996f94dd5-btnqk -- 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 03:15:35.580: 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-hrxgj-6996f94dd5-btnqk -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:15:36.707: INFO: stderr: "" Jan 4 03:15:36.707: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/04/23 03:15:36.707[0m Jan 4 03:15:36.707: INFO: Deleting pod "azuredisk-volume-tester-hrxgj-6996f94dd5-btnqk" in namespace "azuredisk-156" ... skipping 83 lines ... Jan 4 03:15:27.944: 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hrxgj-6996f94dd5\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 4 03:15:29.943: 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 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, 3, 14, 45, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 4, 3, 14, 45, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-hrxgj-6996f94dd5\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 03:15:32.16[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 03:15:32.375[0m Jan 4 03:15:32.375: 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-hrxgj-6996f94dd5-btnqk -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:15:33.580: INFO: rc: 1 Jan 4 03:15:33.580: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-hrxgj-6996f94dd5-btnqk": 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-hrxgj-6996f94dd5-btnqk -- 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 03:15:35.580: 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-hrxgj-6996f94dd5-btnqk -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:15:36.707: INFO: stderr: "" Jan 4 03:15:36.707: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/04/23 03:15:36.707[0m Jan 4 03:15:36.707: INFO: Deleting pod "azuredisk-volume-tester-hrxgj-6996f94dd5-btnqk" in namespace "azuredisk-156" ... skipping 309 lines ... Jan 4 03:17:20.374: INFO: PersistentVolumeClaim pvc-z7tmv found and phase=Bound (4.314641974s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:17:20.374[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:17:20.479[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:17:20.582[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:17:20.582[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:17:20.582[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:17:20.69[0m Jan 4 03:17:20.690: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-ts2lk" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 4 03:17:20.802: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 111.73204ms Jan 4 03:17:22.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224465512s Jan 4 03:17:24.913: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22260187s Jan 4 03:17:26.916: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.225065774s Jan 4 03:17:28.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224107354s Jan 4 03:17:30.916: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.225081571s ... skipping 29 lines ... Jan 4 03:18:30.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=true. Elapsed: 1m10.224404324s Jan 4 03:18:32.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=false. Elapsed: 1m12.225013112s Jan 4 03:18:34.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=false. Elapsed: 1m14.224871769s Jan 4 03:18:36.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.224905867s Jan 4 03:18:38.914: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m18.223986815s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:18:38.915[0m Jan 4 03:18:38.915: INFO: Pod "azuredisk-volume-tester-ts2lk" satisfied condition "Succeeded or Failed" Jan 4 03:18:38.915: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-ts2lk" Jan 4 03:18:39.041: INFO: Pod azuredisk-volume-tester-ts2lk has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-ts2lk in namespace azuredisk-1598 [38;5;243m01/04/23 03:18:39.041[0m ... skipping 87 lines ... Jan 4 03:17:20.374: INFO: PersistentVolumeClaim pvc-z7tmv found and phase=Bound (4.314641974s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:17:20.374[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:17:20.479[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:17:20.582[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:17:20.582[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:17:20.582[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:17:20.69[0m Jan 4 03:17:20.690: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-ts2lk" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 4 03:17:20.802: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 111.73204ms Jan 4 03:17:22.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224465512s Jan 4 03:17:24.913: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22260187s Jan 4 03:17:26.916: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.225065774s Jan 4 03:17:28.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224107354s Jan 4 03:17:30.916: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.225081571s ... skipping 29 lines ... Jan 4 03:18:30.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=true. Elapsed: 1m10.224404324s Jan 4 03:18:32.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=false. Elapsed: 1m12.225013112s Jan 4 03:18:34.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=false. Elapsed: 1m14.224871769s Jan 4 03:18:36.915: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.224905867s Jan 4 03:18:38.914: INFO: Pod "azuredisk-volume-tester-ts2lk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m18.223986815s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:18:38.915[0m Jan 4 03:18:38.915: INFO: Pod "azuredisk-volume-tester-ts2lk" satisfied condition "Succeeded or Failed" Jan 4 03:18:38.915: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-ts2lk" Jan 4 03:18:39.041: INFO: Pod azuredisk-volume-tester-ts2lk has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-ts2lk in namespace azuredisk-1598 [38;5;243m01/04/23 03:18:39.041[0m ... skipping 95 lines ... Jan 4 03:19:47.223: INFO: PersistentVolumeClaim pvc-8zt5j found but phase is Pending instead of Bound. Jan 4 03:19:49.328: INFO: PersistentVolumeClaim pvc-8zt5j found and phase=Bound (4.32856092s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:19:49.328[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:19:49.433[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:19:49.537[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:19:49.537[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:19:49.649[0m Jan 4 03:19:49.649: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-w2dfn" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 4 03:19:49.754: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 105.013848ms Jan 4 03:19:51.860: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.211012157s Jan 4 03:19:53.862: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.212695917s Jan 4 03:19:55.859: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.210051057s Jan 4 03:19:57.861: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.211324444s Jan 4 03:19:59.860: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210580466s ... skipping 18 lines ... Jan 4 03:20:37.868: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=true. Elapsed: 48.218084526s Jan 4 03:20:39.868: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=false. Elapsed: 50.218449366s Jan 4 03:20:41.873: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=false. Elapsed: 52.223761383s Jan 4 03:20:43.867: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=false. Elapsed: 54.217925284s Jan 4 03:20:45.869: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 56.219986494s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:20:45.869[0m Jan 4 03:20:45.870: INFO: Pod "azuredisk-volume-tester-w2dfn" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 03:20:45.87[0m [1mSTEP:[0m Prow test resource group: capz-00jd55 [38;5;243m01/04/23 03:20:45.871[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-c7291ac5-8bde-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:20:45.871[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-c7291ac5-8bde-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:20:48.537[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 03:20:48.538[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 03:20:48.538[0m ... skipping 11 lines ... Jan 4 03:21:08.415: INFO: PersistentVolumeClaim pvc-8v52t found and phase=Bound (4.318283137s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:21:08.415[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:21:08.519[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:21:08.624[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:21:08.624[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 03:21:08.624[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:21:08.735[0m Jan 4 03:21:08.735: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jv8j5" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 4 03:21:08.840: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 104.303672ms Jan 4 03:21:10.953: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217456522s Jan 4 03:21:12.945: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.20990846s Jan 4 03:21:14.946: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.210315014s Jan 4 03:21:16.944: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209126671s Jan 4 03:21:18.944: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209074961s ... skipping 11 lines ... Jan 4 03:21:42.952: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=true. Elapsed: 34.216734245s Jan 4 03:21:44.954: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=true. Elapsed: 36.219119314s Jan 4 03:21:46.953: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=true. Elapsed: 38.217693966s Jan 4 03:21:48.961: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=false. Elapsed: 40.225235404s Jan 4 03:21:50.951: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.215419269s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:21:50.951[0m Jan 4 03:21:50.951: INFO: Pod "azuredisk-volume-tester-jv8j5" satisfied condition "Succeeded or Failed" Jan 4 03:21:50.951: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-jv8j5" Jan 4 03:21:51.078: INFO: Pod azuredisk-volume-tester-jv8j5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-jv8j5 in namespace azuredisk-8582 [38;5;243m01/04/23 03:21:51.079[0m Jan 4 03:21:51.212: INFO: deleting PVC "azuredisk-8582"/"pvc-8v52t" Jan 4 03:21:51.212: INFO: Deleting PersistentVolumeClaim "pvc-8v52t" ... skipping 54 lines ... Jan 4 03:19:47.223: INFO: PersistentVolumeClaim pvc-8zt5j found but phase is Pending instead of Bound. Jan 4 03:19:49.328: INFO: PersistentVolumeClaim pvc-8zt5j found and phase=Bound (4.32856092s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:19:49.328[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:19:49.433[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:19:49.537[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:19:49.537[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:19:49.649[0m Jan 4 03:19:49.649: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-w2dfn" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 4 03:19:49.754: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 105.013848ms Jan 4 03:19:51.860: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.211012157s Jan 4 03:19:53.862: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.212695917s Jan 4 03:19:55.859: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.210051057s Jan 4 03:19:57.861: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.211324444s Jan 4 03:19:59.860: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210580466s ... skipping 18 lines ... Jan 4 03:20:37.868: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=true. Elapsed: 48.218084526s Jan 4 03:20:39.868: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=false. Elapsed: 50.218449366s Jan 4 03:20:41.873: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=false. Elapsed: 52.223761383s Jan 4 03:20:43.867: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Running", Reason="", readiness=false. Elapsed: 54.217925284s Jan 4 03:20:45.869: INFO: Pod "azuredisk-volume-tester-w2dfn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 56.219986494s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:20:45.869[0m Jan 4 03:20:45.870: INFO: Pod "azuredisk-volume-tester-w2dfn" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 03:20:45.87[0m [1mSTEP:[0m Prow test resource group: capz-00jd55 [38;5;243m01/04/23 03:20:45.871[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-c7291ac5-8bde-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:20:45.871[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-c7291ac5-8bde-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:20:48.537[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 03:20:48.538[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 03:20:48.538[0m ... skipping 11 lines ... Jan 4 03:21:08.415: INFO: PersistentVolumeClaim pvc-8v52t found and phase=Bound (4.318283137s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:21:08.415[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:21:08.519[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:21:08.624[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:21:08.624[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 03:21:08.624[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:21:08.735[0m Jan 4 03:21:08.735: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jv8j5" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 4 03:21:08.840: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 104.303672ms Jan 4 03:21:10.953: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217456522s Jan 4 03:21:12.945: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.20990846s Jan 4 03:21:14.946: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.210315014s Jan 4 03:21:16.944: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209126671s Jan 4 03:21:18.944: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209074961s ... skipping 11 lines ... Jan 4 03:21:42.952: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=true. Elapsed: 34.216734245s Jan 4 03:21:44.954: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=true. Elapsed: 36.219119314s Jan 4 03:21:46.953: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=true. Elapsed: 38.217693966s Jan 4 03:21:48.961: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Running", Reason="", readiness=false. Elapsed: 40.225235404s Jan 4 03:21:50.951: INFO: Pod "azuredisk-volume-tester-jv8j5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.215419269s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:21:50.951[0m Jan 4 03:21:50.951: INFO: Pod "azuredisk-volume-tester-jv8j5" satisfied condition "Succeeded or Failed" Jan 4 03:21:50.951: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-jv8j5" Jan 4 03:21:51.078: INFO: Pod azuredisk-volume-tester-jv8j5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-jv8j5 in namespace azuredisk-8582 [38;5;243m01/04/23 03:21:51.079[0m Jan 4 03:21:51.212: INFO: deleting PVC "azuredisk-8582"/"pvc-8v52t" Jan 4 03:21:51.212: INFO: Deleting PersistentVolumeClaim "pvc-8v52t" ... skipping 53 lines ... Jan 4 03:24:06.382: INFO: PersistentVolumeClaim pvc-ls8fk found but phase is Pending instead of Bound. Jan 4 03:24:08.488: INFO: PersistentVolumeClaim pvc-ls8fk found and phase=Bound (4.319866156s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:24:08.488[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:24:08.594[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:24:08.698[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:24:08.698[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:24:08.811[0m Jan 4 03:24:08.811: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-c86pq" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 4 03:24:08.915: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 104.050888ms Jan 4 03:24:11.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209389212s Jan 4 03:24:13.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209299328s Jan 4 03:24:15.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209039308s Jan 4 03:24:17.021: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209958403s Jan 4 03:24:19.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209549303s ... skipping 15 lines ... Jan 4 03:24:51.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=true. Elapsed: 42.215755468s Jan 4 03:24:53.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=false. Elapsed: 44.215745897s Jan 4 03:24:55.028: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=false. Elapsed: 46.217398044s Jan 4 03:24:57.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=false. Elapsed: 48.215668128s Jan 4 03:24:59.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 50.215722093s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:24:59.027[0m Jan 4 03:24:59.027: INFO: Pod "azuredisk-volume-tester-c86pq" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 03:24:59.027[0m [1mSTEP:[0m Prow test resource group: capz-00jd55 [38;5;243m01/04/23 03:24:59.028[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-5e0dc891-8bdf-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:24:59.028[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-5e0dc891-8bdf-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:24:59.839[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 03:24:59.839[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 03:24:59.839[0m ... skipping 29 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:25:44.048[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:25:44.153[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:25:44.257[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:25:44.258[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/04/23 03:25:44.258[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 03:25:44.258[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:25:44.372[0m Jan 4 03:25:44.372: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-8w9b8" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 4 03:25:44.481: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 108.777829ms Jan 4 03:25:46.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.214834331s Jan 4 03:25:48.586: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.214610146s Jan 4 03:25:50.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.214780129s Jan 4 03:25:52.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.215244194s Jan 4 03:25:54.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.214978501s ... skipping 236 lines ... Jan 4 03:33:48.592: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=true. Elapsed: 8m4.220413577s Jan 4 03:33:50.594: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=true. Elapsed: 8m6.222107659s Jan 4 03:33:52.591: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=true. Elapsed: 8m8.219339884s Jan 4 03:33:54.593: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=false. Elapsed: 8m10.221172761s Jan 4 03:33:56.593: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8m12.220918884s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:33:56.593[0m Jan 4 03:33:56.593: INFO: Pod "azuredisk-volume-tester-8w9b8" satisfied condition "Succeeded or Failed" Jan 4 03:33:56.593: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-8w9b8" Jan 4 03:33:56.725: INFO: Pod azuredisk-volume-tester-8w9b8 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-8w9b8 in namespace azuredisk-7726 [38;5;243m01/04/23 03:33:56.726[0m Jan 4 03:33:56.927: INFO: deleting PVC "azuredisk-7726"/"pvc-rc8t7" Jan 4 03:33:56.927: INFO: Deleting PersistentVolumeClaim "pvc-rc8t7" ... skipping 57 lines ... Jan 4 03:24:06.382: INFO: PersistentVolumeClaim pvc-ls8fk found but phase is Pending instead of Bound. Jan 4 03:24:08.488: INFO: PersistentVolumeClaim pvc-ls8fk found and phase=Bound (4.319866156s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:24:08.488[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:24:08.594[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:24:08.698[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:24:08.698[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:24:08.811[0m Jan 4 03:24:08.811: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-c86pq" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 4 03:24:08.915: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 104.050888ms Jan 4 03:24:11.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209389212s Jan 4 03:24:13.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209299328s Jan 4 03:24:15.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209039308s Jan 4 03:24:17.021: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209958403s Jan 4 03:24:19.020: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.209549303s ... skipping 15 lines ... Jan 4 03:24:51.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=true. Elapsed: 42.215755468s Jan 4 03:24:53.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=false. Elapsed: 44.215745897s Jan 4 03:24:55.028: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=false. Elapsed: 46.217398044s Jan 4 03:24:57.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Running", Reason="", readiness=false. Elapsed: 48.215668128s Jan 4 03:24:59.026: INFO: Pod "azuredisk-volume-tester-c86pq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 50.215722093s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:24:59.027[0m Jan 4 03:24:59.027: INFO: Pod "azuredisk-volume-tester-c86pq" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/04/23 03:24:59.027[0m [1mSTEP:[0m Prow test resource group: capz-00jd55 [38;5;243m01/04/23 03:24:59.028[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-5e0dc891-8bdf-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:24:59.028[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-5e0dc891-8bdf-11ed-8aa2-b6580070620b [38;5;243m01/04/23 03:24:59.839[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/04/23 03:24:59.839[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/04/23 03:24:59.839[0m ... skipping 29 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:25:44.048[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:25:44.153[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:25:44.257[0m [1mSTEP:[0m setting up the pod [38;5;243m01/04/23 03:25:44.258[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/04/23 03:25:44.258[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/04/23 03:25:44.258[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:25:44.372[0m Jan 4 03:25:44.372: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-8w9b8" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 4 03:25:44.481: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 108.777829ms Jan 4 03:25:46.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.214834331s Jan 4 03:25:48.586: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.214610146s Jan 4 03:25:50.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.214780129s Jan 4 03:25:52.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.215244194s Jan 4 03:25:54.587: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.214978501s ... skipping 236 lines ... Jan 4 03:33:48.592: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=true. Elapsed: 8m4.220413577s Jan 4 03:33:50.594: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=true. Elapsed: 8m6.222107659s Jan 4 03:33:52.591: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=true. Elapsed: 8m8.219339884s Jan 4 03:33:54.593: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Running", Reason="", readiness=false. Elapsed: 8m10.221172761s Jan 4 03:33:56.593: INFO: Pod "azuredisk-volume-tester-8w9b8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8m12.220918884s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:33:56.593[0m Jan 4 03:33:56.593: INFO: Pod "azuredisk-volume-tester-8w9b8" satisfied condition "Succeeded or Failed" Jan 4 03:33:56.593: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-8w9b8" Jan 4 03:33:56.725: INFO: Pod azuredisk-volume-tester-8w9b8 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-8w9b8 in namespace azuredisk-7726 [38;5;243m01/04/23 03:33:56.726[0m Jan 4 03:33:56.927: INFO: deleting PVC "azuredisk-7726"/"pvc-rc8t7" Jan 4 03:33:56.927: INFO: Deleting PersistentVolumeClaim "pvc-rc8t7" ... skipping 80 lines ... Jan 4 03:36:21.957: INFO: PersistentVolumeClaim pvc-gqsnb found but phase is Pending instead of Bound. Jan 4 03:36:24.062: INFO: PersistentVolumeClaim pvc-gqsnb found and phase=Bound (4.31391505s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:36:24.062[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:36:24.166[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:36:24.27[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:36:24.27[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:36:24.382[0m Jan 4 03:36:24.382: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-n2ds5" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 4 03:36:24.499: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 116.721473ms Jan 4 03:36:26.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.228494109s Jan 4 03:36:28.611: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22960594s Jan 4 03:36:30.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.228264777s Jan 4 03:36:32.612: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.22999546s Jan 4 03:36:34.612: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.230289006s ... skipping 26 lines ... Jan 4 03:37:28.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=true. Elapsed: 1m4.22848954s Jan 4 03:37:30.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=true. Elapsed: 1m6.227715302s Jan 4 03:37:32.611: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=true. Elapsed: 1m8.229594649s Jan 4 03:37:34.614: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.232513195s Jan 4 03:37:36.611: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m12.228847184s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:37:36.611[0m Jan 4 03:37:36.611: INFO: Pod "azuredisk-volume-tester-n2ds5" satisfied condition "Succeeded or Failed" Jan 4 03:37:36.611: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-n2ds5" Jan 4 03:37:36.746: INFO: Pod azuredisk-volume-tester-n2ds5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-n2ds5 in namespace azuredisk-3086 [38;5;243m01/04/23 03:37:36.746[0m Jan 4 03:37:36.873: INFO: deleting PVC "azuredisk-3086"/"pvc-gqsnb" Jan 4 03:37:36.873: INFO: Deleting PersistentVolumeClaim "pvc-gqsnb" ... skipping 88 lines ... Jan 4 03:36:21.957: INFO: PersistentVolumeClaim pvc-gqsnb found but phase is Pending instead of Bound. Jan 4 03:36:24.062: INFO: PersistentVolumeClaim pvc-gqsnb found and phase=Bound (4.31391505s) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:36:24.062[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:36:24.166[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:36:24.27[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:36:24.27[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 03:36:24.382[0m Jan 4 03:36:24.382: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-n2ds5" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 4 03:36:24.499: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 116.721473ms Jan 4 03:36:26.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.228494109s Jan 4 03:36:28.611: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22960594s Jan 4 03:36:30.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.228264777s Jan 4 03:36:32.612: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.22999546s Jan 4 03:36:34.612: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.230289006s ... skipping 26 lines ... Jan 4 03:37:28.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=true. Elapsed: 1m4.22848954s Jan 4 03:37:30.610: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=true. Elapsed: 1m6.227715302s Jan 4 03:37:32.611: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=true. Elapsed: 1m8.229594649s Jan 4 03:37:34.614: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.232513195s Jan 4 03:37:36.611: INFO: Pod "azuredisk-volume-tester-n2ds5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m12.228847184s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 03:37:36.611[0m Jan 4 03:37:36.611: INFO: Pod "azuredisk-volume-tester-n2ds5" satisfied condition "Succeeded or Failed" Jan 4 03:37:36.611: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-n2ds5" Jan 4 03:37:36.746: INFO: Pod azuredisk-volume-tester-n2ds5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-n2ds5 in namespace azuredisk-3086 [38;5;243m01/04/23 03:37:36.746[0m Jan 4 03:37:36.873: INFO: deleting PVC "azuredisk-3086"/"pvc-gqsnb" Jan 4 03:37:36.873: INFO: Deleting PersistentVolumeClaim "pvc-gqsnb" ... skipping 789 lines ... I0104 03:56:38.944260 37904 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0104 03:56:40.944667 37904 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 03:56:41.055[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 03:56:41.167[0m Jan 4 03:56:41.167: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4535 exec azuredisk-volume-tester-cqgrz-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:56:42.430: INFO: rc: 1 Jan 4 03:56:42.430: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-cqgrz-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4535 exec azuredisk-volume-tester-cqgrz-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 03:56:44.431: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4535 exec azuredisk-volume-tester-cqgrz-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:56:45.545: INFO: stderr: "" Jan 4 03:56:45.545: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/04/23 03:56:45.545[0m Jan 4 03:56:45.546: INFO: Deleting pod "azuredisk-volume-tester-cqgrz-0" in namespace "azuredisk-4535" ... skipping 64 lines ... I0104 03:56:38.944260 37904 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0104 03:56:40.944667 37904 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/04/23 03:56:41.055[0m [1mSTEP:[0m check pod exec [38;5;243m01/04/23 03:56:41.167[0m Jan 4 03:56:41.167: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4535 exec azuredisk-volume-tester-cqgrz-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:56:42.430: INFO: rc: 1 Jan 4 03:56:42.430: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-cqgrz-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4535 exec azuredisk-volume-tester-cqgrz-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 03:56:44.431: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4535 exec azuredisk-volume-tester-cqgrz-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 4 03:56:45.545: INFO: stderr: "" Jan 4 03:56:45.545: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/04/23 03:56:45.545[0m Jan 4 03:56:45.546: INFO: Deleting pod "azuredisk-volume-tester-cqgrz-0" in namespace "azuredisk-4535" ... skipping 184 lines ... Jan 4 03:58:08.323: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-t826s] to have phase Bound Jan 4 03:58:08.427: INFO: PersistentVolumeClaim pvc-t826s found and phase=Bound (103.901733ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:58:08.427[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:58:08.532[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:58:08.636[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:58:08.637[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 03:58:08.747[0m Jan 4 03:58:08.747: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-s2xb6" in namespace "azuredisk-3447" to be "Error status code" Jan 4 03:58:08.850: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 103.750012ms Jan 4 03:58:10.956: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209245469s Jan 4 03:58:12.959: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.211842003s Jan 4 03:58:14.958: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.211570181s Jan 4 03:58:16.962: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21480311s Jan 4 03:58:18.957: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210116718s ... skipping 22 lines ... Jan 4 03:59:04.962: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=true. Elapsed: 56.21566274s Jan 4 03:59:06.963: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=true. Elapsed: 58.216219269s Jan 4 03:59:08.963: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=true. Elapsed: 1m0.216204758s Jan 4 03:59:10.962: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.215587378s Jan 4 03:59:12.963: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=false. Elapsed: 1m4.216441997s Jan 4 03:59:14.965: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=false. Elapsed: 1m6.218703672s Jan 4 03:59:16.964: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Failed", Reason="", readiness=false. Elapsed: 1m8.216853461s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 03:59:16.964[0m Jan 4 03:59:16.964: INFO: Pod "azuredisk-volume-tester-s2xb6" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 03:59:16.964[0m Jan 4 03:59:17.087: INFO: deleting Pod "azuredisk-3447"/"azuredisk-volume-tester-s2xb6" Jan 4 03:59:17.201: INFO: Pod azuredisk-volume-tester-s2xb6 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 55 lines ... Jan 4 03:58:08.323: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-t826s] to have phase Bound Jan 4 03:58:08.427: INFO: PersistentVolumeClaim pvc-t826s found and phase=Bound (103.901733ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 03:58:08.427[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 03:58:08.532[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 03:58:08.636[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 03:58:08.637[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/04/23 03:58:08.747[0m Jan 4 03:58:08.747: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-s2xb6" in namespace "azuredisk-3447" to be "Error status code" Jan 4 03:58:08.850: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 103.750012ms Jan 4 03:58:10.956: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209245469s Jan 4 03:58:12.959: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.211842003s Jan 4 03:58:14.958: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.211570181s Jan 4 03:58:16.962: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21480311s Jan 4 03:58:18.957: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210116718s ... skipping 22 lines ... Jan 4 03:59:04.962: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=true. Elapsed: 56.21566274s Jan 4 03:59:06.963: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=true. Elapsed: 58.216219269s Jan 4 03:59:08.963: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=true. Elapsed: 1m0.216204758s Jan 4 03:59:10.962: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.215587378s Jan 4 03:59:12.963: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=false. Elapsed: 1m4.216441997s Jan 4 03:59:14.965: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Running", Reason="", readiness=false. Elapsed: 1m6.218703672s Jan 4 03:59:16.964: INFO: Pod "azuredisk-volume-tester-s2xb6": Phase="Failed", Reason="", readiness=false. Elapsed: 1m8.216853461s [1mSTEP:[0m Saw pod failure [38;5;243m01/04/23 03:59:16.964[0m Jan 4 03:59:16.964: INFO: Pod "azuredisk-volume-tester-s2xb6" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/04/23 03:59:16.964[0m Jan 4 03:59:17.087: INFO: deleting Pod "azuredisk-3447"/"azuredisk-volume-tester-s2xb6" Jan 4 03:59:17.201: INFO: Pod azuredisk-volume-tester-s2xb6 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-00jd55/providers/Microsoft.Compute/disks/single-shared-disk" [38;5;243m01/04/23 03:59:58.41[0m [1mSTEP:[0m Destroying namespace "azuredisk-1853" for this suite. [38;5;243m01/04/23 03:59:59.211[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 03:59:59.318[0m Jan 4 03:59:59.318: 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 03:59:59.319[0m [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m01/04/23 03:59:59.638[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m01/04/23 03:59:59.845[0m ... skipping 2 lines ... [38;5;243m------------------------------[0m [38;5;10m• [0.844 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 03:59:59.318[0m Jan 4 03:59:59.318: 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 03:59:59.319[0m ... skipping 88 lines ... Jan 4 04:00:53.981: INFO: PersistentVolumeClaim pvc-jdz85 found and phase=Bound (103.895898ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 04:00:53.981[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 04:00:54.085[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 04:00:54.19[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/04/23 04:00:54.344[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 04:01:03.355[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 04:01:03.465[0m Jan 4 04:01:03.465: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-mcczh" in namespace "azuredisk-2804" to be "Succeeded or Failed" Jan 4 04:01:03.580: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 114.831729ms Jan 4 04:01:05.684: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219536848s Jan 4 04:01:07.685: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.220625283s Jan 4 04:01:09.684: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219280251s Jan 4 04:01:11.690: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224664365s Jan 4 04:01:13.687: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.221740761s ... skipping 29 lines ... Jan 4 04:02:13.692: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=true. Elapsed: 1m10.227628777s Jan 4 04:02:15.692: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=true. Elapsed: 1m12.22716657s Jan 4 04:02:17.690: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=false. Elapsed: 1m14.225581733s Jan 4 04:02:19.691: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.226444716s Jan 4 04:02:21.692: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m18.226905024s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 04:02:21.692[0m Jan 4 04:02:21.692: INFO: Pod "azuredisk-volume-tester-mcczh" satisfied condition "Succeeded or Failed" Jan 4 04:02:21.692: INFO: deleting Pod "azuredisk-2804"/"azuredisk-volume-tester-mcczh" Jan 4 04:02:21.821: INFO: Pod azuredisk-volume-tester-mcczh has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-mcczh in namespace azuredisk-2804 [38;5;243m01/04/23 04:02:21.821[0m Jan 4 04:02:22.187: INFO: deleting PVC "azuredisk-2804"/"pvc-jdz85" Jan 4 04:02:22.187: INFO: Deleting PersistentVolumeClaim "pvc-jdz85" ... skipping 36 lines ... Jan 4 04:00:53.981: INFO: PersistentVolumeClaim pvc-jdz85 found and phase=Bound (103.895898ms) [1mSTEP:[0m checking the PVC [38;5;243m01/04/23 04:00:53.981[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/04/23 04:00:54.085[0m [1mSTEP:[0m checking the PV [38;5;243m01/04/23 04:00:54.19[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/04/23 04:00:54.344[0m [1mSTEP:[0m deploying the pod [38;5;243m01/04/23 04:01:03.355[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/04/23 04:01:03.465[0m Jan 4 04:01:03.465: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-mcczh" in namespace "azuredisk-2804" to be "Succeeded or Failed" Jan 4 04:01:03.580: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 114.831729ms Jan 4 04:01:05.684: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219536848s Jan 4 04:01:07.685: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.220625283s Jan 4 04:01:09.684: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219280251s Jan 4 04:01:11.690: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.224664365s Jan 4 04:01:13.687: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.221740761s ... skipping 29 lines ... Jan 4 04:02:13.692: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=true. Elapsed: 1m10.227628777s Jan 4 04:02:15.692: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=true. Elapsed: 1m12.22716657s Jan 4 04:02:17.690: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=false. Elapsed: 1m14.225581733s Jan 4 04:02:19.691: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.226444716s Jan 4 04:02:21.692: INFO: Pod "azuredisk-volume-tester-mcczh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m18.226905024s [1mSTEP:[0m Saw pod success [38;5;243m01/04/23 04:02:21.692[0m Jan 4 04:02:21.692: INFO: Pod "azuredisk-volume-tester-mcczh" satisfied condition "Succeeded or Failed" Jan 4 04:02:21.692: INFO: deleting Pod "azuredisk-2804"/"azuredisk-volume-tester-mcczh" Jan 4 04:02:21.821: INFO: Pod azuredisk-volume-tester-mcczh has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-mcczh in namespace azuredisk-2804 [38;5;243m01/04/23 04:02:21.821[0m Jan 4 04:02:22.187: INFO: deleting PVC "azuredisk-2804"/"pvc-jdz85" Jan 4 04:02:22.187: INFO: Deleting PersistentVolumeClaim "pvc-jdz85" ... skipping 116 lines ... Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0104 02:56:24.594701 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31 e2e-test I0104 02:56:24.596153 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0104 02:56:24.618535 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 22 milliseconds I0104 02:56:24.619051 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 02:56:24.619072 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 02:56:24.619082 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0104 02:56:24.619247 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0104 02:56:24.620085 1 azure_auth.go:245] Using AzurePublicCloud environment I0104 02:56:24.620234 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 02:56:24.620751 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0104 02:56:24.621069 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0104 02:56:24.621339 1 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0104 02:56:24.621390 1 azuredisk.go:192] disable UseInstanceMetadata for controller I0104 02:56:24.621416 1 azuredisk.go:204] cloud: AzurePublicCloud, location: northeurope, rg: capz-00jd55, VMType: vmss, PrimaryScaleSetName: , PrimaryAvailabilitySetName: , DisableAvailabilitySetNodes: false I0104 02:56:24.627229 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount2288571594' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount2288571594: must be superuser to unmount. I0104 02:56:24.627289 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0104 02:56:24.627518 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0104 02:56:24.627539 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0104 02:56:24.627548 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0104 02:56:24.627581 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0104 02:56:24.627600 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 182 lines ... I0104 03:04:27.894469 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.19138379 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-00jd55" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/pvc-ab4208b2-117c-474f-8524-10c979342e20" result_code="succeeded" I0104 03:04:27.894489 1 utils.go:84] GRPC response: {} I0104 03:04:34.552535 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0104 03:04:34.552784 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-1e806a61-03ac-4591-8889-5910b5f0cab1","parameters":{"csi.storage.k8s.io/pv/name":"pvc-1e806a61-03ac-4591-8889-5910b5f0cab1","csi.storage.k8s.io/pvc/name":"pvc-pnvp5","csi.storage.k8s.io/pvc/namespace":"azuredisk-2540","enableAsyncAttach":"false","networkAccessPolicy":"DenyAll","skuName":"Standard_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0104 03:04:34.553818 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0104 03:04:34.569960 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 15 milliseconds I0104 03:04:34.570315 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 03:04:34.570531 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 03:04:34.570676 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0104 03:04:34.571084 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0104 03:04:34.571575 1 azure_auth.go:245] Using AzurePublicCloud environment I0104 03:04:34.571802 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 03:04:34.572052 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 76 lines ... I0104 03:06:16.066297 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.24997811 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-00jd55" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/pvc-1e806a61-03ac-4591-8889-5910b5f0cab1" result_code="succeeded" I0104 03:06:16.066318 1 utils.go:84] GRPC response: {} I0104 03:06:22.677221 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0104 03:06:22.677246 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-0a0e6905-5925-484d-ae7f-b64e6303ccc5","parameters":{"csi.storage.k8s.io/pv/name":"pvc-0a0e6905-5925-484d-ae7f-b64e6303ccc5","csi.storage.k8s.io/pvc/name":"pvc-qkhwj","csi.storage.k8s.io/pvc/namespace":"azuredisk-4728","enableAsyncAttach":"false","enableBursting":"true","perfProfile":"Basic","skuName":"Premium_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0104 03:06:22.678386 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0104 03:06:22.698056 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 19 milliseconds I0104 03:06:22.698240 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 03:06:22.698254 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 03:06:22.698263 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0104 03:06:22.698308 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0104 03:06:22.698625 1 azure_auth.go:245] Using AzurePublicCloud environment I0104 03:06:22.698672 1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 03:06:22.698737 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 1676 lines ... I0104 03:51:14.560304 1 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0104 03:51:14.560342 1 utils.go:78] GRPC request: {} I0104 03:51:14.560435 1 utils.go:84] GRPC response: {"ready":{"value":true}} I0104 03:51:44.561671 1 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0104 03:51:44.561696 1 utils.go:78] GRPC request: {} I0104 03:51:44.561767 1 utils.go:84] GRPC response: {"ready":{"value":true}} I0104 03:51:59.324622 1 azure_armclient.go:291] Received error in WaitForAsyncOperationCompletion: 'Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded' I0104 03:51:59.325250 1 azure_armclient.go:451] Received error in WaitForAsyncOperationResult: 'Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded', no response I0104 03:51:59.325716 1 azure_diskclient.go:273] Received error in disk.put.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/pvc-fc5eaa1c-e6b7-4e41-8850-6592c7f3cdee, error: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded I0104 03:51:59.326023 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=239.909565401 request="disks_update" resource_group="capz-00jd55" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="" I0104 03:51:59.326267 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=239.948155047 request="azuredisk_csi_driver_controller_expand_volume" resource_group="capz-00jd55" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/pvc-fc5eaa1c-e6b7-4e41-8850-6592c7f3cdee" result_code="failed_csi_driver_controller_expand_volume" E0104 03:51:59.326462 1 utils.go:82] GRPC error: rpc error: code = Internal desc = failed to resize disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/pvc-fc5eaa1c-e6b7-4e41-8850-6592c7f3cdee) with error(Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded) I0104 03:52:00.341884 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I0104 03:52:00.341918 1 utils.go:78] GRPC request: {} I0104 03:52:00.342319 1 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":13}}}]} I0104 03:52:00.347649 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerExpandVolume I0104 03:52:00.348243 1 utils.go:78] GRPC request: {"capacity_range":{"required_bytes":21474836480},"volume_capability":{"AccessType":{"Mount":{"mount_flags":["barrier=1","acl"]}},"access_mode":{"mode":7}},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/pvc-fc5eaa1c-e6b7-4e41-8850-6592c7f3cdee"} I0104 03:52:00.378337 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 1372 ... skipping 461 lines ... I0104 04:01:19.155533 1 azure_controller_standard.go:236] azureDisk - update(capz-00jd55): vm(capz-00jd-5nnsv) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-00jd55/providers/microsoft.compute/disks/reattach-disk-multiple-nodes:reattach-disk-multiple-nodes]) returned with <nil> I0104 04:01:19.155630 1 azure_controller_standard.go:126] DeleteCacheForNode(capz-00jd-5nnsv) successfully I0104 04:01:19.155721 1 azure_controller_standard.go:272] updateCache(capz-00jd-5nnsv) successfully I0104 04:01:19.155735 1 azure_controller_common.go:422] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded I0104 04:01:19.155977 1 controllerserver.go:425] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-00jd-8z6zr again I0104 04:01:19.156032 1 azure_controller_common.go:194] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-00jd-5nnsv, could not be attached to node(capz-00jd-8z6zr) E0104 04:01:19.156096 1 controllerserver.go:429] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-00jd-8z6zr failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/virtualMachines/capz-00jd-5nnsv), could not be attached to node(capz-00jd-8z6zr) I0104 04:01:19.156270 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=15.551356724 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-00jd55" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="capz-00jd-8z6zr" result_code="failed_csi_driver_controller_publish_volume" E0104 04:01:19.156300 1 utils.go:82] GRPC error: rpc error: code = Internal desc = Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-00jd-8z6zr failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/virtualMachines/capz-00jd-5nnsv), could not be attached to node(capz-00jd-8z6zr) I0104 04:01:19.171527 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume I0104 04:01:19.171552 1 utils.go:78] GRPC request: {"node_id":"capz-00jd-8z6zr","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-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"} I0104 04:01:19.211895 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 973 I0104 04:01:19.212278 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.040223347 request="disks_get" resource_group="capz-00jd55" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="" I0104 04:01:19.212377 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-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-00jd-8z6zr (vmState Succeeded). I0104 04:01:19.212459 1 controllerserver.go:408] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-00jd55/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-00jd-8z6zr ... skipping 141 lines ... Go Version: go1.19.4 Platform: windows/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0104 02:56:32.010061 3508 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31 e2e-test W0104 02:56:32.011549 3508 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 02:56:32.011549 3508 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 02:56:32.011549 3508 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0104 02:56:32.012053 3508 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0104 02:56:32.013046 3508 azure_auth.go:245] Using AzurePublicCloud environment I0104 02:56:32.013046 3508 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 02:56:32.016552 3508 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 20 lines ... I0104 02:56:32.430590 3508 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31"} I0104 02:56:32.981708 3508 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo I0104 02:56:32.981708 3508 utils.go:78] GRPC request: {} I0104 02:56:32.981708 3508 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31"} I0104 02:56:33.970323 3508 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo I0104 02:56:33.970323 3508 utils.go:78] GRPC request: {} I0104 02:56:34.004312 3508 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0104 02:56:34.004445 3508 nodeserver.go:370] NodeGetInfo: nodeName(capz-00jd-8z6zr), VM Size(Standard_D4s_v3) I0104 02:56:34.004445 3508 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8 I0104 02:56:34.004445 3508 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-00jd-8z6zr"} I0104 02:56:49.102188 3508 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities I0104 02:56:49.102188 3508 utils.go:78] GRPC request: {} I0104 02:56:49.102188 3508 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]} ... skipping 1433 lines ... Go Version: go1.19.4 Platform: windows/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0104 02:56:38.212281 2544 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31 e2e-test W0104 02:56:38.214410 2544 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 02:56:38.214735 2544 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0104 02:56:38.214775 2544 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0104 02:56:38.214892 2544 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0104 02:56:38.217172 2544 azure_auth.go:245] Using AzurePublicCloud environment I0104 02:56:38.217350 2544 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token I0104 02:56:38.221304 2544 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 20 lines ... I0104 02:56:38.511910 2544 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31"} I0104 02:56:38.815179 2544 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo I0104 02:56:38.815225 2544 utils.go:78] GRPC request: {} I0104 02:56:38.815225 2544 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.26.0-c5139edbb80a8677f61bd420ac1b58e4aac70a31"} I0104 02:56:39.345234 2544 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo I0104 02:56:39.345234 2544 utils.go:78] GRPC request: {} I0104 02:56:39.373695 2544 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0104 02:56:39.378279 2544 nodeserver.go:370] NodeGetInfo: nodeName(capz-00jd-5nnsv), VM Size(Standard_D4s_v3) I0104 02:56:39.378279 2544 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8 I0104 02:56:39.378279 2544 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-00jd-5nnsv"} I0104 02:57:14.218406 2544 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0104 02:57:14.218582 2544 utils.go:78] GRPC request: {} I0104 02:57:14.218653 2544 utils.go:84] GRPC response: {"ready":{"value":true}} ... skipping 1271 lines ... cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 40 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 40 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 40 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 40 cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 514.380918041 cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 40 # 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_expand_volume",resource_group="capz-00jd55",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1 cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-00jd55",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 ... skipping 68 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 51181 # 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 31571 # 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 [159.931 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 24 of 66 Specs in 4921.432 seconds[0m [38;5;10m[1mSUCCESS![0m -- [38;5;10m[1m24 Passed[0m | [38;5;9m[1m0 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m42 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 39 lines ... Jan 4 04:10:39.129: INFO: Collecting logs for Windows node capz-00jd-8z6zr in cluster capz-00jd55 in namespace default Jan 4 04:12:19.281: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-00jd-8z6zr to /logs/artifacts/clusters/capz-00jd55/machines/capz-00jd55-md-win-f549c487-m445l/crashdumps.tar Jan 4 04:12:22.719: INFO: Collecting boot logs for AzureMachine capz-00jd55-md-win-8z6zr Failed to get logs for machine capz-00jd55-md-win-f549c487-m445l, cluster default/capz-00jd55: 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 04:12:24.001: INFO: Collecting logs for Windows node capz-00jd-5nnsv in cluster capz-00jd55 in namespace default Jan 4 04:14:02.349: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-00jd-5nnsv to /logs/artifacts/clusters/capz-00jd55/machines/capz-00jd55-md-win-f549c487-s4t8p/crashdumps.tar Jan 4 04:14:06.155: INFO: Collecting boot logs for AzureMachine capz-00jd55-md-win-5nnsv Failed to get logs for machine capz-00jd55-md-win-f549c487-s4t8p, cluster default/capz-00jd55: 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 [1mSTEP[0m: Dumping workload cluster default/capz-00jd55 kube-system pod logs [1mSTEP[0m: Fetching kube-system pod logs took 1.351496836s [1mSTEP[0m: Dumping workload cluster default/capz-00jd55 Azure activity log [1mSTEP[0m: Collecting events for Pod kube-system/csi-proxy-9ffbb [1mSTEP[0m: Creating log watcher for controller kube-system/calico-node-windows-j8flq, container calico-node-startup [1mSTEP[0m: Creating log watcher for controller kube-system/coredns-bd6b6df9f-462pt, container coredns [1mSTEP[0m: Collecting events for Pod kube-system/kube-proxy-wmzp2 [1mSTEP[0m: failed to find events of Pod "kube-proxy-wmzp2" [1mSTEP[0m: Creating log watcher for controller kube-system/metrics-server-7bdcf69694-dz8tk, container metrics-server [1mSTEP[0m: Collecting events for Pod kube-system/containerd-logger-vjhkl [1mSTEP[0m: Collecting events for Pod kube-system/kube-scheduler-capz-00jd55-control-plane-2fg4f [1mSTEP[0m: Collecting events for Pod kube-system/metrics-server-7bdcf69694-dz8tk [1mSTEP[0m: Creating log watcher for controller kube-system/calico-kube-controllers-85f479877b-b22p7, container calico-kube-controllers [1mSTEP[0m: Creating log watcher for controller kube-system/calico-node-l2psb, container calico-node [1mSTEP[0m: failed to find events of Pod "kube-scheduler-capz-00jd55-control-plane-2fg4f" [1mSTEP[0m: Collecting events for Pod kube-system/calico-node-windows-j8flq [1mSTEP[0m: failed to find events of Pod "calico-node-windows-j8flq" [1mSTEP[0m: Creating log watcher for controller kube-system/calico-node-windows-j8flq, container calico-node-felix [1mSTEP[0m: Creating log watcher for controller kube-system/calico-node-windows-mqk94, container calico-node-startup [1mSTEP[0m: Collecting events for Pod kube-system/kube-proxy-windows-5lgsr [1mSTEP[0m: Collecting events for Pod kube-system/calico-node-l2psb [1mSTEP[0m: failed to find events of Pod "calico-node-l2psb" [1mSTEP[0m: failed to find events of Pod "kube-proxy-windows-5lgsr" [1mSTEP[0m: Collecting events for Pod kube-system/csi-proxy-ttjf7 [1mSTEP[0m: Creating log watcher for controller kube-system/csi-proxy-ttjf7, container csi-proxy [1mSTEP[0m: failed to find events of Pod "csi-proxy-ttjf7" [1mSTEP[0m: Creating log watcher for controller kube-system/etcd-capz-00jd55-control-plane-2fg4f, container etcd [1mSTEP[0m: Creating log watcher for controller kube-system/kube-apiserver-capz-00jd55-control-plane-2fg4f, container kube-apiserver [1mSTEP[0m: Collecting events for Pod kube-system/kube-apiserver-capz-00jd55-control-plane-2fg4f [1mSTEP[0m: failed to find events of Pod "kube-apiserver-capz-00jd55-control-plane-2fg4f" [1mSTEP[0m: Creating log watcher for controller kube-system/kube-controller-manager-capz-00jd55-control-plane-2fg4f, container kube-controller-manager [1mSTEP[0m: Collecting events for Pod kube-system/kube-controller-manager-capz-00jd55-control-plane-2fg4f [1mSTEP[0m: failed to find events of Pod "kube-controller-manager-capz-00jd55-control-plane-2fg4f" [1mSTEP[0m: Creating log watcher for controller kube-system/kube-proxy-windows-5lgsr, container kube-proxy [1mSTEP[0m: Creating log watcher for controller kube-system/calico-node-windows-mqk94, container calico-node-felix [1mSTEP[0m: Collecting events for Pod kube-system/etcd-capz-00jd55-control-plane-2fg4f [1mSTEP[0m: failed to find events of Pod "etcd-capz-00jd55-control-plane-2fg4f" [1mSTEP[0m: Creating log watcher for controller kube-system/coredns-bd6b6df9f-qmcbd, container coredns [1mSTEP[0m: Collecting events for Pod kube-system/coredns-bd6b6df9f-qmcbd [1mSTEP[0m: Collecting events for Pod kube-system/containerd-logger-crwj6 [1mSTEP[0m: Creating log watcher for controller kube-system/containerd-logger-crwj6, container containerd-logger [1mSTEP[0m: Creating log watcher for controller kube-system/csi-proxy-9ffbb, container csi-proxy [1mSTEP[0m: Creating log watcher for controller kube-system/containerd-logger-vjhkl, container containerd-logger [1mSTEP[0m: Creating log watcher for controller kube-system/kube-scheduler-capz-00jd55-control-plane-2fg4f, container kube-scheduler [1mSTEP[0m: Creating log watcher for controller kube-system/kube-proxy-windows-wk7xf, container kube-proxy [1mSTEP[0m: Collecting events for Pod kube-system/kube-proxy-windows-wk7xf [1mSTEP[0m: Creating log watcher for controller kube-system/kube-proxy-wmzp2, container kube-proxy [1mSTEP[0m: Collecting events for Pod kube-system/calico-kube-controllers-85f479877b-b22p7 [1mSTEP[0m: failed to find events of Pod "containerd-logger-vjhkl" [1mSTEP[0m: Collecting events for Pod kube-system/coredns-bd6b6df9f-462pt [1mSTEP[0m: failed to find events of Pod "metrics-server-7bdcf69694-dz8tk" [1mSTEP[0m: failed to find events of Pod "coredns-bd6b6df9f-qmcbd" [1mSTEP[0m: failed to find events of Pod "containerd-logger-crwj6" [1mSTEP[0m: Collecting events for Pod kube-system/calico-node-windows-mqk94 [1mSTEP[0m: failed to find events of Pod "calico-node-windows-mqk94" [1mSTEP[0m: failed to find events of Pod "csi-proxy-9ffbb" [1mSTEP[0m: failed to find events of Pod "kube-proxy-windows-wk7xf" [1mSTEP[0m: failed to find events of Pod "calico-kube-controllers-85f479877b-b22p7" [1mSTEP[0m: failed to find events of Pod "coredns-bd6b6df9f-462pt" [1mSTEP[0m: Got error while iterating over activity logs for resource group capz-00jd55: 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 [1mSTEP[0m: Fetching activity logs took 7.0177679s ================ REDACTING LOGS ================ All sensitive variables are redacted cluster.cluster.x-k8s.io "capz-00jd55" 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-04T04:20:30Z"} ++ early_exit_handler ++ '[' -n 160 ']' ++ kill -TERM 160 ++ 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-04T04:21:15Z"}