kubernetes-sigs/azuredisk-csi-driver PR #1704 pull-azuredisk-csi-driver-e2e-capz #1619333791875076096
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | andyzhangx: fix: switch base image to fix CVEs |
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 1h43m |
| Revision | a093a52191d3e3d9e4045b29bef24ef84b1ddc4f |
| Refs |
1704 |
... skipping 785 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 127 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-epg8q8-kubeconfig; do sleep 1; done" capz-epg8q8-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-epg8q8-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-epg8q8-control-plane-gz6b5 NotReady control-plane 8s v1.24.6 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' pod/kube-apiserver-capz-epg8q8-control-plane-gz6b5 condition met namespace/calico-system created NAME DATA AGE ... skipping 78 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 187k 0 --:--:-- --:--:-- --:--:-- 187k Downloading https://get.helm.sh/helm-v3.11.0-linux-amd64.tar.gz Verifying checksum... Done. Preparing to install helm into /usr/local/bin helm installed into /usr/local/bin/helm docker pull capzci.azurecr.io/azuredisk-csi:v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 || make container-all push-manifest Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 not found: manifest unknown: manifest tagged by "v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7" is not found make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver' CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.driverVersion=v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=15a7100a0e7ccd86606f3f693bffc000489534a7 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-28T14:14:08Z -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 1099 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 865 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 28 14:20:31.792: INFO: PersistentVolumeClaim pvc-ft2wp found and phase=Bound (4.307789036s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:20:31.792[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:20:31.896[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:20:31.999[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:20:31.999[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:20:31.999[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:20:32.103[0m Jan 28 14:20:32.104: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-sg2lg" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 28 14:20:32.208: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 104.262265ms Jan 28 14:20:34.311: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207382808s Jan 28 14:20:36.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207857993s Jan 28 14:20:38.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.208029509s Jan 28 14:20:40.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.20812657s Jan 28 14:20:42.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208571861s Jan 28 14:20:44.313: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 12.209541065s Jan 28 14:20:46.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 14.207858631s Jan 28 14:20:48.318: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 16.21462409s Jan 28 14:20:50.319: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Running", Reason="", readiness=false. Elapsed: 18.215076192s Jan 28 14:20:52.320: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.216336148s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:20:52.32[0m Jan 28 14:20:52.321: INFO: Pod "azuredisk-volume-tester-sg2lg" satisfied condition "Succeeded or Failed" Jan 28 14:20:52.321: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-sg2lg" Jan 28 14:20:52.437: INFO: Pod azuredisk-volume-tester-sg2lg has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-sg2lg in namespace azuredisk-8081 [38;5;243m01/28/23 14:20:52.437[0m Jan 28 14:20:52.554: INFO: deleting PVC "azuredisk-8081"/"pvc-ft2wp" Jan 28 14:20:52.554: INFO: Deleting PersistentVolumeClaim "pvc-ft2wp" ... skipping 63 lines ... Jan 28 14:20:31.792: INFO: PersistentVolumeClaim pvc-ft2wp found and phase=Bound (4.307789036s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:20:31.792[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:20:31.896[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:20:31.999[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:20:31.999[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:20:31.999[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:20:32.103[0m Jan 28 14:20:32.104: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-sg2lg" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 28 14:20:32.208: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 104.262265ms Jan 28 14:20:34.311: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207382808s Jan 28 14:20:36.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207857993s Jan 28 14:20:38.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.208029509s Jan 28 14:20:40.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.20812657s Jan 28 14:20:42.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208571861s Jan 28 14:20:44.313: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 12.209541065s Jan 28 14:20:46.312: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 14.207858631s Jan 28 14:20:48.318: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Pending", Reason="", readiness=false. Elapsed: 16.21462409s Jan 28 14:20:50.319: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Running", Reason="", readiness=false. Elapsed: 18.215076192s Jan 28 14:20:52.320: INFO: Pod "azuredisk-volume-tester-sg2lg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.216336148s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:20:52.32[0m Jan 28 14:20:52.321: INFO: Pod "azuredisk-volume-tester-sg2lg" satisfied condition "Succeeded or Failed" Jan 28 14:20:52.321: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-sg2lg" Jan 28 14:20:52.437: INFO: Pod azuredisk-volume-tester-sg2lg has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-sg2lg in namespace azuredisk-8081 [38;5;243m01/28/23 14:20:52.437[0m Jan 28 14:20:52.554: INFO: deleting PVC "azuredisk-8081"/"pvc-ft2wp" Jan 28 14:20:52.554: INFO: Deleting PersistentVolumeClaim "pvc-ft2wp" ... skipping 37 lines ... Jan 28 14:21:37.860: INFO: PersistentVolumeClaim pvc-vbxgn found but phase is Pending instead of Bound. Jan 28 14:21:39.963: INFO: PersistentVolumeClaim pvc-vbxgn found and phase=Bound (4.308663245s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:21:39.963[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:21:40.068[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:21:40.171[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:21:40.172[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/28/23 14:21:40.276[0m Jan 28 14:21:40.276: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-nqxx4" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 28 14:21:40.381: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 104.30766ms Jan 28 14:21:42.488: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.211540595s Jan 28 14:21:44.484: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207960212s Jan 28 14:21:46.484: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.208148959s Jan 28 14:21:48.485: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.208509226s Jan 28 14:21:50.492: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21548245s Jan 28 14:21:52.491: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.214485318s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:21:52.491[0m Jan 28 14:21:52.491: INFO: Pod "azuredisk-volume-tester-nqxx4" satisfied condition "Succeeded or Failed" Jan 28 14:21:52.491: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-nqxx4" Jan 28 14:21:52.596: INFO: Pod azuredisk-volume-tester-nqxx4 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-nqxx4 in namespace azuredisk-2540 [38;5;243m01/28/23 14:21:52.596[0m Jan 28 14:21:52.715: INFO: deleting PVC "azuredisk-2540"/"pvc-vbxgn" Jan 28 14:21:52.715: INFO: Deleting PersistentVolumeClaim "pvc-vbxgn" ... skipping 38 lines ... Jan 28 14:21:37.860: INFO: PersistentVolumeClaim pvc-vbxgn found but phase is Pending instead of Bound. Jan 28 14:21:39.963: INFO: PersistentVolumeClaim pvc-vbxgn found and phase=Bound (4.308663245s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:21:39.963[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:21:40.068[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:21:40.171[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:21:40.172[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/28/23 14:21:40.276[0m Jan 28 14:21:40.276: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-nqxx4" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 28 14:21:40.381: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 104.30766ms Jan 28 14:21:42.488: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.211540595s Jan 28 14:21:44.484: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207960212s Jan 28 14:21:46.484: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.208148959s Jan 28 14:21:48.485: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.208509226s Jan 28 14:21:50.492: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21548245s Jan 28 14:21:52.491: INFO: Pod "azuredisk-volume-tester-nqxx4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.214485318s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:21:52.491[0m Jan 28 14:21:52.491: INFO: Pod "azuredisk-volume-tester-nqxx4" satisfied condition "Succeeded or Failed" Jan 28 14:21:52.491: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-nqxx4" Jan 28 14:21:52.596: INFO: Pod azuredisk-volume-tester-nqxx4 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-nqxx4 in namespace azuredisk-2540 [38;5;243m01/28/23 14:21:52.596[0m Jan 28 14:21:52.715: INFO: deleting PVC "azuredisk-2540"/"pvc-vbxgn" Jan 28 14:21:52.715: INFO: Deleting PersistentVolumeClaim "pvc-vbxgn" ... skipping 38 lines ... Jan 28 14:22:40.409: INFO: PersistentVolumeClaim pvc-84bzz found and phase=Bound (4.429431866s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:22:40.409[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:22:40.512[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:22:40.615[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:22:40.615[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:22:40.616[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:22:40.72[0m Jan 28 14:22:40.721: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zqkv4" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 28 14:22:40.823: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 101.981495ms Jan 28 14:22:42.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204830818s Jan 28 14:22:44.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205089347s Jan 28 14:22:46.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.20514718s Jan 28 14:22:48.927: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.206494152s Jan 28 14:22:50.927: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20624633s ... skipping 10 lines ... Jan 28 14:23:12.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 32.205023744s Jan 28 14:23:14.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 34.204997649s Jan 28 14:23:16.927: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 36.205677321s Jan 28 14:23:18.934: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Running", Reason="", readiness=false. Elapsed: 38.213147194s Jan 28 14:23:20.935: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 40.213859274s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:23:20.935[0m Jan 28 14:23:20.935: INFO: Pod "azuredisk-volume-tester-zqkv4" satisfied condition "Succeeded or Failed" Jan 28 14:23:20.935: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-zqkv4" Jan 28 14:23:21.048: INFO: Pod azuredisk-volume-tester-zqkv4 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-zqkv4 in namespace azuredisk-4728 [38;5;243m01/28/23 14:23:21.048[0m Jan 28 14:23:21.163: INFO: deleting PVC "azuredisk-4728"/"pvc-84bzz" Jan 28 14:23:21.164: INFO: Deleting PersistentVolumeClaim "pvc-84bzz" ... skipping 39 lines ... Jan 28 14:22:40.409: INFO: PersistentVolumeClaim pvc-84bzz found and phase=Bound (4.429431866s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:22:40.409[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:22:40.512[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:22:40.615[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:22:40.615[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:22:40.616[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:22:40.72[0m Jan 28 14:22:40.721: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zqkv4" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 28 14:22:40.823: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 101.981495ms Jan 28 14:22:42.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204830818s Jan 28 14:22:44.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205089347s Jan 28 14:22:46.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.20514718s Jan 28 14:22:48.927: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.206494152s Jan 28 14:22:50.927: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20624633s ... skipping 10 lines ... Jan 28 14:23:12.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 32.205023744s Jan 28 14:23:14.926: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 34.204997649s Jan 28 14:23:16.927: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Pending", Reason="", readiness=false. Elapsed: 36.205677321s Jan 28 14:23:18.934: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Running", Reason="", readiness=false. Elapsed: 38.213147194s Jan 28 14:23:20.935: INFO: Pod "azuredisk-volume-tester-zqkv4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 40.213859274s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:23:20.935[0m Jan 28 14:23:20.935: INFO: Pod "azuredisk-volume-tester-zqkv4" satisfied condition "Succeeded or Failed" Jan 28 14:23:20.935: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-zqkv4" Jan 28 14:23:21.048: INFO: Pod azuredisk-volume-tester-zqkv4 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-zqkv4 in namespace azuredisk-4728 [38;5;243m01/28/23 14:23:21.048[0m Jan 28 14:23:21.163: INFO: deleting PVC "azuredisk-4728"/"pvc-84bzz" Jan 28 14:23:21.164: INFO: Deleting PersistentVolumeClaim "pvc-84bzz" ... skipping 40 lines ... [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:24:08.676[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:24:08.778[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:24:08.778[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:24:08.779[0m [1mSTEP:[0m checking that the pod has 'FailedMount' event [38;5;243m01/28/23 14:24:08.882[0m Jan 28 14:24:21.087: INFO: deleting Pod "azuredisk-5466"/"azuredisk-volume-tester-gtfgx" Jan 28 14:24:21.190: INFO: Error getting logs for pod azuredisk-volume-tester-gtfgx: the server rejected our request for an unknown reason (get pods azuredisk-volume-tester-gtfgx) [1mSTEP:[0m Deleting pod azuredisk-volume-tester-gtfgx in namespace azuredisk-5466 [38;5;243m01/28/23 14:24:21.19[0m Jan 28 14:24:21.296: INFO: deleting PVC "azuredisk-5466"/"pvc-4nfrw" Jan 28 14:24:21.296: INFO: Deleting PersistentVolumeClaim "pvc-4nfrw" [1mSTEP:[0m waiting for claim's PV "pvc-30d6646f-6737-45e5-94f6-7889b8c29201" to be deleted [38;5;243m01/28/23 14:24:21.398[0m Jan 28 14:24:21.398: INFO: Waiting up to 10m0s for PersistentVolume pvc-30d6646f-6737-45e5-94f6-7889b8c29201 to get deleted Jan 28 14:24:21.500: INFO: PersistentVolume pvc-30d6646f-6737-45e5-94f6-7889b8c29201 found and phase=Bound (102.068585ms) ... skipping 59 lines ... [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:24:08.676[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:24:08.778[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:24:08.778[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:24:08.779[0m [1mSTEP:[0m checking that the pod has 'FailedMount' event [38;5;243m01/28/23 14:24:08.882[0m Jan 28 14:24:21.087: INFO: deleting Pod "azuredisk-5466"/"azuredisk-volume-tester-gtfgx" Jan 28 14:24:21.190: INFO: Error getting logs for pod azuredisk-volume-tester-gtfgx: the server rejected our request for an unknown reason (get pods azuredisk-volume-tester-gtfgx) [1mSTEP:[0m Deleting pod azuredisk-volume-tester-gtfgx in namespace azuredisk-5466 [38;5;243m01/28/23 14:24:21.19[0m Jan 28 14:24:21.296: INFO: deleting PVC "azuredisk-5466"/"pvc-4nfrw" Jan 28 14:24:21.296: INFO: Deleting PersistentVolumeClaim "pvc-4nfrw" [1mSTEP:[0m waiting for claim's PV "pvc-30d6646f-6737-45e5-94f6-7889b8c29201" to be deleted [38;5;243m01/28/23 14:24:21.398[0m Jan 28 14:24:21.398: INFO: Waiting up to 10m0s for PersistentVolume pvc-30d6646f-6737-45e5-94f6-7889b8c29201 to get deleted Jan 28 14:24:21.500: INFO: PersistentVolume pvc-30d6646f-6737-45e5-94f6-7889b8c29201 found and phase=Bound (102.068585ms) ... skipping 56 lines ... Jan 28 14:26:55.832: INFO: PersistentVolumeClaim pvc-6cngc found and phase=Bound (4.307603675s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:26:55.832[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:26:55.934[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:26:56.036[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:26:56.037[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:26:56.037[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:26:56.14[0m Jan 28 14:26:56.140: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5tk7h" in namespace "azuredisk-2790" to be "Succeeded or Failed" Jan 28 14:26:56.241: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 101.450509ms Jan 28 14:26:58.344: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204583722s Jan 28 14:27:00.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205540656s Jan 28 14:27:02.343: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 6.203668926s Jan 28 14:27:04.344: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204056515s Jan 28 14:27:06.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205342702s Jan 28 14:27:08.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 12.205028555s Jan 28 14:27:10.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205332229s Jan 28 14:27:12.351: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Running", Reason="", readiness=true. Elapsed: 16.211090356s Jan 28 14:27:14.351: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Running", Reason="", readiness=false. Elapsed: 18.211663297s Jan 28 14:27:16.352: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.212375067s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:27:16.352[0m Jan 28 14:27:16.352: INFO: Pod "azuredisk-volume-tester-5tk7h" satisfied condition "Succeeded or Failed" Jan 28 14:27:16.352: INFO: deleting Pod "azuredisk-2790"/"azuredisk-volume-tester-5tk7h" Jan 28 14:27:16.473: INFO: Pod azuredisk-volume-tester-5tk7h has the following logs: e2e-test [1mSTEP:[0m Deleting pod azuredisk-volume-tester-5tk7h in namespace azuredisk-2790 [38;5;243m01/28/23 14:27:16.473[0m Jan 28 14:27:16.586: INFO: deleting PVC "azuredisk-2790"/"pvc-6cngc" Jan 28 14:27:16.586: INFO: Deleting PersistentVolumeClaim "pvc-6cngc" ... skipping 39 lines ... Jan 28 14:26:55.832: INFO: PersistentVolumeClaim pvc-6cngc found and phase=Bound (4.307603675s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:26:55.832[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:26:55.934[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:26:56.036[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:26:56.037[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:26:56.037[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:26:56.14[0m Jan 28 14:26:56.140: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5tk7h" in namespace "azuredisk-2790" to be "Succeeded or Failed" Jan 28 14:26:56.241: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 101.450509ms Jan 28 14:26:58.344: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204583722s Jan 28 14:27:00.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205540656s Jan 28 14:27:02.343: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 6.203668926s Jan 28 14:27:04.344: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204056515s Jan 28 14:27:06.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205342702s Jan 28 14:27:08.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 12.205028555s Jan 28 14:27:10.345: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205332229s Jan 28 14:27:12.351: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Running", Reason="", readiness=true. Elapsed: 16.211090356s Jan 28 14:27:14.351: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Running", Reason="", readiness=false. Elapsed: 18.211663297s Jan 28 14:27:16.352: INFO: Pod "azuredisk-volume-tester-5tk7h": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.212375067s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:27:16.352[0m Jan 28 14:27:16.352: INFO: Pod "azuredisk-volume-tester-5tk7h" satisfied condition "Succeeded or Failed" Jan 28 14:27:16.352: INFO: deleting Pod "azuredisk-2790"/"azuredisk-volume-tester-5tk7h" Jan 28 14:27:16.473: INFO: Pod azuredisk-volume-tester-5tk7h has the following logs: e2e-test [1mSTEP:[0m Deleting pod azuredisk-volume-tester-5tk7h in namespace azuredisk-2790 [38;5;243m01/28/23 14:27:16.473[0m Jan 28 14:27:16.586: INFO: deleting PVC "azuredisk-2790"/"pvc-6cngc" Jan 28 14:27:16.586: INFO: Deleting PersistentVolumeClaim "pvc-6cngc" ... skipping 41 lines ... Jan 28 14:28:03.444: INFO: PersistentVolumeClaim pvc-tckrc found but phase is Pending instead of Bound. Jan 28 14:28:05.546: INFO: PersistentVolumeClaim pvc-tckrc found and phase=Bound (4.306640493s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:28:05.546[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:28:05.648[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:28:05.749[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:28:05.749[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:28:05.853[0m Jan 28 14:28:05.853: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-hffnh" in namespace "azuredisk-5356" to be "Succeeded or Failed" Jan 28 14:28:05.956: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 102.611423ms Jan 28 14:28:08.058: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204913697s Jan 28 14:28:10.060: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206110165s Jan 28 14:28:12.059: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205869426s Jan 28 14:28:14.059: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205288563s Jan 28 14:28:16.060: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206139188s Jan 28 14:28:18.058: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 12.204847561s Jan 28 14:28:20.065: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 14.211421362s Jan 28 14:28:22.066: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 16.212133423s Jan 28 14:28:24.067: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.213569119s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:28:24.067[0m Jan 28 14:28:24.067: INFO: Pod "azuredisk-volume-tester-hffnh" satisfied condition "Succeeded or Failed" Jan 28 14:28:24.067: INFO: deleting Pod "azuredisk-5356"/"azuredisk-volume-tester-hffnh" Jan 28 14:28:24.171: INFO: Pod azuredisk-volume-tester-hffnh has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-hffnh in namespace azuredisk-5356 [38;5;243m01/28/23 14:28:24.171[0m Jan 28 14:28:24.380: INFO: deleting PVC "azuredisk-5356"/"pvc-tckrc" Jan 28 14:28:24.380: INFO: Deleting PersistentVolumeClaim "pvc-tckrc" ... skipping 39 lines ... Jan 28 14:28:03.444: INFO: PersistentVolumeClaim pvc-tckrc found but phase is Pending instead of Bound. Jan 28 14:28:05.546: INFO: PersistentVolumeClaim pvc-tckrc found and phase=Bound (4.306640493s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:28:05.546[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:28:05.648[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:28:05.749[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:28:05.749[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:28:05.853[0m Jan 28 14:28:05.853: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-hffnh" in namespace "azuredisk-5356" to be "Succeeded or Failed" Jan 28 14:28:05.956: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 102.611423ms Jan 28 14:28:08.058: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204913697s Jan 28 14:28:10.060: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206110165s Jan 28 14:28:12.059: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205869426s Jan 28 14:28:14.059: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205288563s Jan 28 14:28:16.060: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206139188s Jan 28 14:28:18.058: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 12.204847561s Jan 28 14:28:20.065: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 14.211421362s Jan 28 14:28:22.066: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Pending", Reason="", readiness=false. Elapsed: 16.212133423s Jan 28 14:28:24.067: INFO: Pod "azuredisk-volume-tester-hffnh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.213569119s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:28:24.067[0m Jan 28 14:28:24.067: INFO: Pod "azuredisk-volume-tester-hffnh" satisfied condition "Succeeded or Failed" Jan 28 14:28:24.067: INFO: deleting Pod "azuredisk-5356"/"azuredisk-volume-tester-hffnh" Jan 28 14:28:24.171: INFO: Pod azuredisk-volume-tester-hffnh has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-hffnh in namespace azuredisk-5356 [38;5;243m01/28/23 14:28:24.171[0m Jan 28 14:28:24.380: INFO: deleting PVC "azuredisk-5356"/"pvc-tckrc" Jan 28 14:28:24.380: INFO: Deleting PersistentVolumeClaim "pvc-tckrc" ... skipping 52 lines ... Jan 28 14:30:13.646: INFO: PersistentVolumeClaim pvc-snwz7 found but phase is Pending instead of Bound. Jan 28 14:30:15.749: INFO: PersistentVolumeClaim pvc-snwz7 found and phase=Bound (4.31062293s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:30:15.749[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:30:15.852[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:30:15.954[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:30:15.954[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:30:16.058[0m Jan 28 14:30:16.058: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-pbqbh" in namespace "azuredisk-5194" to be "Succeeded or Failed" Jan 28 14:30:16.160: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 101.921629ms Jan 28 14:30:18.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205875061s Jan 28 14:30:20.263: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205224557s Jan 28 14:30:22.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206268654s Jan 28 14:30:24.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205811182s Jan 28 14:30:26.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20605396s ... skipping 2 lines ... Jan 28 14:30:32.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 16.205898087s Jan 28 14:30:34.263: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 18.204662079s Jan 28 14:30:36.271: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 20.212782846s Jan 28 14:30:38.271: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 22.212853445s Jan 28 14:30:40.271: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 24.212888866s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:30:40.271[0m Jan 28 14:30:40.271: INFO: Pod "azuredisk-volume-tester-pbqbh" satisfied condition "Succeeded or Failed" Jan 28 14:30:40.271: INFO: deleting Pod "azuredisk-5194"/"azuredisk-volume-tester-pbqbh" Jan 28 14:30:40.393: INFO: Pod azuredisk-volume-tester-pbqbh has the following logs: hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-pbqbh in namespace azuredisk-5194 [38;5;243m01/28/23 14:30:40.393[0m Jan 28 14:30:40.509: INFO: deleting PVC "azuredisk-5194"/"pvc-snwz7" ... skipping 74 lines ... Jan 28 14:30:13.646: INFO: PersistentVolumeClaim pvc-snwz7 found but phase is Pending instead of Bound. Jan 28 14:30:15.749: INFO: PersistentVolumeClaim pvc-snwz7 found and phase=Bound (4.31062293s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:30:15.749[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:30:15.852[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:30:15.954[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:30:15.954[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:30:16.058[0m Jan 28 14:30:16.058: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-pbqbh" in namespace "azuredisk-5194" to be "Succeeded or Failed" Jan 28 14:30:16.160: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 101.921629ms Jan 28 14:30:18.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205875061s Jan 28 14:30:20.263: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205224557s Jan 28 14:30:22.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206268654s Jan 28 14:30:24.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205811182s Jan 28 14:30:26.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20605396s ... skipping 2 lines ... Jan 28 14:30:32.264: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 16.205898087s Jan 28 14:30:34.263: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 18.204662079s Jan 28 14:30:36.271: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 20.212782846s Jan 28 14:30:38.271: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Pending", Reason="", readiness=false. Elapsed: 22.212853445s Jan 28 14:30:40.271: INFO: Pod "azuredisk-volume-tester-pbqbh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 24.212888866s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:30:40.271[0m Jan 28 14:30:40.271: INFO: Pod "azuredisk-volume-tester-pbqbh" satisfied condition "Succeeded or Failed" Jan 28 14:30:40.271: INFO: deleting Pod "azuredisk-5194"/"azuredisk-volume-tester-pbqbh" Jan 28 14:30:40.393: INFO: Pod azuredisk-volume-tester-pbqbh has the following logs: hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-pbqbh in namespace azuredisk-5194 [38;5;243m01/28/23 14:30:40.393[0m Jan 28 14:30:40.509: INFO: deleting PVC "azuredisk-5194"/"pvc-snwz7" ... skipping 56 lines ... Jan 28 14:34:41.017: INFO: PersistentVolumeClaim pvc-zcjb8 found and phase=Bound (4.309250626s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:34:41.017[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:34:41.119[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:34:41.221[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:34:41.221[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:34:41.221[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 14:34:41.325[0m Jan 28 14:34:41.325: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-s77d7" in namespace "azuredisk-1353" to be "Error status code" Jan 28 14:34:41.427: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 102.236948ms Jan 28 14:34:43.529: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204691665s Jan 28 14:34:45.531: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205876799s Jan 28 14:34:47.530: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205561576s Jan 28 14:34:49.531: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.206075504s Jan 28 14:34:51.532: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206793004s Jan 28 14:34:53.530: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 12.204794799s Jan 28 14:34:55.530: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205169224s Jan 28 14:34:57.536: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Running", Reason="", readiness=false. Elapsed: 16.211570044s Jan 28 14:34:59.536: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Failed", Reason="", readiness=false. Elapsed: 18.211625028s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 14:34:59.537[0m Jan 28 14:34:59.537: INFO: Pod "azuredisk-volume-tester-s77d7" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 14:34:59.537[0m Jan 28 14:34:59.653: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-s77d7" Jan 28 14:34:59.757: INFO: Pod azuredisk-volume-tester-s77d7 has the following logs: touch: /mnt/test-1/data: Read-only file system [1mSTEP:[0m Deleting pod azuredisk-volume-tester-s77d7 in namespace azuredisk-1353 [38;5;243m01/28/23 14:34:59.757[0m Jan 28 14:34:59.884: INFO: deleting PVC "azuredisk-1353"/"pvc-zcjb8" ... skipping 37 lines ... Jan 28 14:34:41.017: INFO: PersistentVolumeClaim pvc-zcjb8 found and phase=Bound (4.309250626s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:34:41.017[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:34:41.119[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:34:41.221[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:34:41.221[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:34:41.221[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 14:34:41.325[0m Jan 28 14:34:41.325: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-s77d7" in namespace "azuredisk-1353" to be "Error status code" Jan 28 14:34:41.427: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 102.236948ms Jan 28 14:34:43.529: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204691665s Jan 28 14:34:45.531: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205876799s Jan 28 14:34:47.530: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205561576s Jan 28 14:34:49.531: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.206075504s Jan 28 14:34:51.532: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206793004s Jan 28 14:34:53.530: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 12.204794799s Jan 28 14:34:55.530: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205169224s Jan 28 14:34:57.536: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Running", Reason="", readiness=false. Elapsed: 16.211570044s Jan 28 14:34:59.536: INFO: Pod "azuredisk-volume-tester-s77d7": Phase="Failed", Reason="", readiness=false. Elapsed: 18.211625028s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 14:34:59.537[0m Jan 28 14:34:59.537: INFO: Pod "azuredisk-volume-tester-s77d7" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 14:34:59.537[0m Jan 28 14:34:59.653: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-s77d7" Jan 28 14:34:59.757: INFO: Pod azuredisk-volume-tester-s77d7 has the following logs: touch: /mnt/test-1/data: Read-only file system [1mSTEP:[0m Deleting pod azuredisk-volume-tester-s77d7 in namespace azuredisk-1353 [38;5;243m01/28/23 14:34:59.757[0m Jan 28 14:34:59.884: INFO: deleting PVC "azuredisk-1353"/"pvc-zcjb8" ... skipping 664 lines ... Jan 28 14:42:30.075: INFO: PersistentVolumeClaim pvc-mrnrm found and phase=Bound (4.309867564s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:42:30.075[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:42:30.178[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:42:30.28[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:42:30.28[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:42:30.281[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:42:30.386[0m Jan 28 14:42:30.386: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-dmztt" in namespace "azuredisk-59" to be "Succeeded or Failed" Jan 28 14:42:30.489: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 102.943685ms Jan 28 14:42:32.592: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206578982s Jan 28 14:42:34.592: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206502493s Jan 28 14:42:36.591: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205691371s Jan 28 14:42:38.593: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.206983843s Jan 28 14:42:40.593: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.207595054s Jan 28 14:42:42.593: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 12.20687011s Jan 28 14:42:44.592: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 14.206515431s Jan 28 14:42:46.598: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 16.212423703s Jan 28 14:42:48.603: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.217752005s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:42:48.604[0m Jan 28 14:42:48.604: INFO: Pod "azuredisk-volume-tester-dmztt" satisfied condition "Succeeded or Failed" [1mSTEP:[0m sleep 5s and then clone volume [38;5;243m01/28/23 14:42:48.604[0m [1mSTEP:[0m cloning existing volume [38;5;243m01/28/23 14:42:53.604[0m [1mSTEP:[0m setting up the PVC and PV [38;5;243m01/28/23 14:42:53.81[0m [1mSTEP:[0m creating a PVC [38;5;243m01/28/23 14:42:53.81[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/28/23 14:42:53.914[0m Jan 28 14:42:53.914: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lwq5z] to have phase Bound ... skipping 6 lines ... Jan 28 14:43:06.636: INFO: PersistentVolumeClaim pvc-lwq5z found and phase=Bound (12.722401126s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:43:06.636[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:43:06.738[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:43:06.872[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:43:06.872[0m [1mSTEP:[0m deploying a second pod with cloned volume [38;5;243m01/28/23 14:43:06.872[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:43:06.975[0m Jan 28 14:43:06.975: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-f24wn" in namespace "azuredisk-59" to be "Succeeded or Failed" Jan 28 14:43:07.077: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 101.777947ms Jan 28 14:43:09.181: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205761347s Jan 28 14:43:11.180: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204795266s Jan 28 14:43:13.180: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204497074s Jan 28 14:43:15.187: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.212180677s Jan 28 14:43:17.187: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21204554s Jan 28 14:43:19.189: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.214229165s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:43:19.189[0m Jan 28 14:43:19.190: INFO: Pod "azuredisk-volume-tester-f24wn" satisfied condition "Succeeded or Failed" Jan 28 14:43:19.190: INFO: deleting Pod "azuredisk-59"/"azuredisk-volume-tester-f24wn" Jan 28 14:43:19.301: INFO: Pod azuredisk-volume-tester-f24wn has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-f24wn in namespace azuredisk-59 [38;5;243m01/28/23 14:43:19.301[0m Jan 28 14:43:19.414: INFO: deleting PVC "azuredisk-59"/"pvc-lwq5z" Jan 28 14:43:19.414: INFO: Deleting PersistentVolumeClaim "pvc-lwq5z" ... skipping 51 lines ... Jan 28 14:42:30.075: INFO: PersistentVolumeClaim pvc-mrnrm found and phase=Bound (4.309867564s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:42:30.075[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:42:30.178[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:42:30.28[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:42:30.28[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:42:30.281[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:42:30.386[0m Jan 28 14:42:30.386: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-dmztt" in namespace "azuredisk-59" to be "Succeeded or Failed" Jan 28 14:42:30.489: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 102.943685ms Jan 28 14:42:32.592: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206578982s Jan 28 14:42:34.592: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206502493s Jan 28 14:42:36.591: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205691371s Jan 28 14:42:38.593: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.206983843s Jan 28 14:42:40.593: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.207595054s Jan 28 14:42:42.593: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 12.20687011s Jan 28 14:42:44.592: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 14.206515431s Jan 28 14:42:46.598: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Pending", Reason="", readiness=false. Elapsed: 16.212423703s Jan 28 14:42:48.603: INFO: Pod "azuredisk-volume-tester-dmztt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.217752005s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:42:48.604[0m Jan 28 14:42:48.604: INFO: Pod "azuredisk-volume-tester-dmztt" satisfied condition "Succeeded or Failed" [1mSTEP:[0m sleep 5s and then clone volume [38;5;243m01/28/23 14:42:48.604[0m [1mSTEP:[0m cloning existing volume [38;5;243m01/28/23 14:42:53.604[0m [1mSTEP:[0m setting up the PVC and PV [38;5;243m01/28/23 14:42:53.81[0m [1mSTEP:[0m creating a PVC [38;5;243m01/28/23 14:42:53.81[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/28/23 14:42:53.914[0m Jan 28 14:42:53.914: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-lwq5z] to have phase Bound ... skipping 6 lines ... Jan 28 14:43:06.636: INFO: PersistentVolumeClaim pvc-lwq5z found and phase=Bound (12.722401126s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:43:06.636[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:43:06.738[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:43:06.872[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:43:06.872[0m [1mSTEP:[0m deploying a second pod with cloned volume [38;5;243m01/28/23 14:43:06.872[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:43:06.975[0m Jan 28 14:43:06.975: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-f24wn" in namespace "azuredisk-59" to be "Succeeded or Failed" Jan 28 14:43:07.077: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 101.777947ms Jan 28 14:43:09.181: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205761347s Jan 28 14:43:11.180: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204795266s Jan 28 14:43:13.180: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204497074s Jan 28 14:43:15.187: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.212180677s Jan 28 14:43:17.187: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21204554s Jan 28 14:43:19.189: INFO: Pod "azuredisk-volume-tester-f24wn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.214229165s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:43:19.189[0m Jan 28 14:43:19.190: INFO: Pod "azuredisk-volume-tester-f24wn" satisfied condition "Succeeded or Failed" Jan 28 14:43:19.190: INFO: deleting Pod "azuredisk-59"/"azuredisk-volume-tester-f24wn" Jan 28 14:43:19.301: INFO: Pod azuredisk-volume-tester-f24wn has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-f24wn in namespace azuredisk-59 [38;5;243m01/28/23 14:43:19.301[0m Jan 28 14:43:19.414: INFO: deleting PVC "azuredisk-59"/"pvc-lwq5z" Jan 28 14:43:19.414: INFO: Deleting PersistentVolumeClaim "pvc-lwq5z" ... skipping 50 lines ... Jan 28 14:44:17.466: INFO: PersistentVolumeClaim pvc-rww6v found and phase=Bound (4.30739745s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:44:17.466[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:44:17.568[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:44:17.67[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:44:17.67[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:44:17.67[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:44:17.773[0m Jan 28 14:44:17.773: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-m4qjn" in namespace "azuredisk-2546" to be "Succeeded or Failed" Jan 28 14:44:17.874: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 101.572575ms Jan 28 14:44:19.978: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204970611s Jan 28 14:44:21.977: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204427758s Jan 28 14:44:23.978: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204863434s Jan 28 14:44:25.978: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205200803s Jan 28 14:44:27.985: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21200227s Jan 28 14:44:29.984: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.211016987s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:44:29.984[0m Jan 28 14:44:29.984: INFO: Pod "azuredisk-volume-tester-m4qjn" satisfied condition "Succeeded or Failed" [1mSTEP:[0m sleep 5s and then clone volume [38;5;243m01/28/23 14:44:29.984[0m [1mSTEP:[0m cloning existing volume [38;5;243m01/28/23 14:44:34.986[0m [1mSTEP:[0m setting up the PVC and PV [38;5;243m01/28/23 14:44:35.191[0m [1mSTEP:[0m creating a PVC [38;5;243m01/28/23 14:44:35.191[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/28/23 14:44:35.294[0m Jan 28 14:44:35.294: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-vgxwx] to have phase Bound ... skipping 2 lines ... Jan 28 14:44:39.603: INFO: PersistentVolumeClaim pvc-vgxwx found and phase=Bound (4.308871487s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:44:39.603[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:44:39.705[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:44:39.807[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:44:39.808[0m [1mSTEP:[0m deploying a second pod with cloned volume [38;5;243m01/28/23 14:44:39.808[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:44:39.911[0m Jan 28 14:44:39.911: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p9w5h" in namespace "azuredisk-2546" to be "Succeeded or Failed" Jan 28 14:44:40.012: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 101.382473ms Jan 28 14:44:42.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204431745s Jan 28 14:44:44.115: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 4.203985242s Jan 28 14:44:46.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205046949s Jan 28 14:44:48.115: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204381015s Jan 28 14:44:50.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204932917s Jan 28 14:44:52.115: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 12.203922439s Jan 28 14:44:54.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205285008s Jan 28 14:44:56.118: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 16.207053019s Jan 28 14:44:58.124: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 18.212790649s Jan 28 14:45:00.123: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 20.211479911s Jan 28 14:45:02.123: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Failed", Reason="", readiness=false. Elapsed: 22.212366488s Jan 28 14:45:02.124: INFO: Unexpected error: <*fmt.wrapError | 0xc000a7efc0>: { msg: "error while waiting for pod azuredisk-2546/azuredisk-volume-tester-p9w5h to be Succeeded or Failed: pod \"azuredisk-volume-tester-p9w5h\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", err: <*errors.errorString | 0xc00054fcb0>{ s: "pod \"azuredisk-volume-tester-p9w5h\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", }, } Jan 28 14:45:02.124: FAIL: error while waiting for pod azuredisk-2546/azuredisk-volume-tester-p9w5h to be Succeeded or Failed: pod "azuredisk-volume-tester-p9w5h" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]} Full Stack Trace sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*TestPod).WaitForSuccess(0x22517b7?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:823 +0x5d sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*DynamicallyProvisionedVolumeCloningTest).Run(0xc0009e9c28, {0x270bd00, 0xc000798340}, 0x6?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_cloning_tester.go:89 +0x5f4 ... skipping 30 lines ... Jan 28 14:45:54.136: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-2546 to be removed Jan 28 14:45:54.239: INFO: Claim "azuredisk-2546" in namespace "pvc-rww6v" doesn't exist in the system Jan 28 14:45:54.239: INFO: deleting StorageClass azuredisk-2546-disk.csi.azure.com-dynamic-sc-4bdm9 [1mSTEP:[0m dump namespace information after failure [38;5;243m01/28/23 14:45:54.343[0m [1mSTEP:[0m Destroying namespace "azuredisk-2546" for this suite. [38;5;243m01/28/23 14:45:54.343[0m [38;5;243m------------------------------[0m [38;5;9m• [FAILED] [102.924 seconds][0m Dynamic Provisioning [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:41[0m [single-az] [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:44[0m [38;5;9m[1m[It] should clone a volume of larger size than the source volume and make sure the filesystem is appropriately adjusted [disk.csi.azure.com][0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:572[0m ... skipping 16 lines ... Jan 28 14:44:17.466: INFO: PersistentVolumeClaim pvc-rww6v found and phase=Bound (4.30739745s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:44:17.466[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:44:17.568[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:44:17.67[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:44:17.67[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:44:17.67[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:44:17.773[0m Jan 28 14:44:17.773: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-m4qjn" in namespace "azuredisk-2546" to be "Succeeded or Failed" Jan 28 14:44:17.874: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 101.572575ms Jan 28 14:44:19.978: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204970611s Jan 28 14:44:21.977: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204427758s Jan 28 14:44:23.978: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204863434s Jan 28 14:44:25.978: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205200803s Jan 28 14:44:27.985: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.21200227s Jan 28 14:44:29.984: INFO: Pod "azuredisk-volume-tester-m4qjn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.211016987s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:44:29.984[0m Jan 28 14:44:29.984: INFO: Pod "azuredisk-volume-tester-m4qjn" satisfied condition "Succeeded or Failed" [1mSTEP:[0m sleep 5s and then clone volume [38;5;243m01/28/23 14:44:29.984[0m [1mSTEP:[0m cloning existing volume [38;5;243m01/28/23 14:44:34.986[0m [1mSTEP:[0m setting up the PVC and PV [38;5;243m01/28/23 14:44:35.191[0m [1mSTEP:[0m creating a PVC [38;5;243m01/28/23 14:44:35.191[0m [1mSTEP:[0m waiting for PVC to be in phase "Bound" [38;5;243m01/28/23 14:44:35.294[0m Jan 28 14:44:35.294: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-vgxwx] to have phase Bound ... skipping 2 lines ... Jan 28 14:44:39.603: INFO: PersistentVolumeClaim pvc-vgxwx found and phase=Bound (4.308871487s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:44:39.603[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:44:39.705[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:44:39.807[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:44:39.808[0m [1mSTEP:[0m deploying a second pod with cloned volume [38;5;243m01/28/23 14:44:39.808[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:44:39.911[0m Jan 28 14:44:39.911: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p9w5h" in namespace "azuredisk-2546" to be "Succeeded or Failed" Jan 28 14:44:40.012: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 101.382473ms Jan 28 14:44:42.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204431745s Jan 28 14:44:44.115: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 4.203985242s Jan 28 14:44:46.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205046949s Jan 28 14:44:48.115: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204381015s Jan 28 14:44:50.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204932917s Jan 28 14:44:52.115: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 12.203922439s Jan 28 14:44:54.116: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205285008s Jan 28 14:44:56.118: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 16.207053019s Jan 28 14:44:58.124: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 18.212790649s Jan 28 14:45:00.123: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Pending", Reason="", readiness=false. Elapsed: 20.211479911s Jan 28 14:45:02.123: INFO: Pod "azuredisk-volume-tester-p9w5h": Phase="Failed", Reason="", readiness=false. Elapsed: 22.212366488s Jan 28 14:45:02.124: INFO: Unexpected error: <*fmt.wrapError | 0xc000a7efc0>: { msg: "error while waiting for pod azuredisk-2546/azuredisk-volume-tester-p9w5h to be Succeeded or Failed: pod \"azuredisk-volume-tester-p9w5h\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", err: <*errors.errorString | 0xc00054fcb0>{ s: "pod \"azuredisk-volume-tester-p9w5h\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", }, } Jan 28 14:45:02.124: FAIL: error while waiting for pod azuredisk-2546/azuredisk-volume-tester-p9w5h to be Succeeded or Failed: pod "azuredisk-volume-tester-p9w5h" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]} Full Stack Trace sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*TestPod).WaitForSuccess(0x22517b7?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:823 +0x5d sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*DynamicallyProvisionedVolumeCloningTest).Run(0xc0009e9c28, {0x270bd00, 0xc000798340}, 0x6?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_cloning_tester.go:89 +0x5f4 ... skipping 31 lines ... Jan 28 14:45:54.239: INFO: Claim "azuredisk-2546" in namespace "pvc-rww6v" doesn't exist in the system Jan 28 14:45:54.239: INFO: deleting StorageClass azuredisk-2546-disk.csi.azure.com-dynamic-sc-4bdm9 [1mSTEP:[0m dump namespace information after failure [38;5;243m01/28/23 14:45:54.343[0m [1mSTEP:[0m Destroying namespace "azuredisk-2546" for this suite. [38;5;243m01/28/23 14:45:54.343[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;9mJan 28 14:45:02.124: error while waiting for pod azuredisk-2546/azuredisk-volume-tester-p9w5h to be Succeeded or Failed: pod "azuredisk-volume-tester-p9w5h" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 14:44:39 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.197.81 PodIPs:[{IP:192.168.197.81}] StartTime:2023-01-28 14:44:39 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-28 14:44:57 +0000 UTC,FinishedAt:2023-01-28 14:44:57 +0000 UTC,ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:registry.k8s.io/e2e-test-images/busybox:1.29-4 ImageID:registry.k8s.io/e2e-test-images/busybox@sha256:2e0f836850e09b8b7cc937681d6194537a09fbd5f6b9e08f4d646a85128e8937 ContainerID:containerd://44404065d4de1c421e230378e9cbc41966bb4015706ec26883fd1808979a23c9 Started:0xc0001336bd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}[0m [38;5;9mIn [1m[It][0m[38;5;9m at: [1m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:823[0m [1mThere were additional failures detected after the initial failure:[0m [38;5;13m[PANICKED][0m [38;5;13mTest Panicked[0m [38;5;13mIn [1m[DeferCleanup (Each)][0m[38;5;13m at: [1m/usr/local/go/src/runtime/panic.go:260[0m [38;5;13mruntime error: invalid memory address or nil pointer dereference[0m [38;5;13mFull Stack Trace[0m k8s.io/kubernetes/test/e2e/framework.(*Framework).dumpNamespaceInfo.func1() /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:274 +0x5c k8s.io/kubernetes/test/e2e/framework.(*Framework).dumpNamespaceInfo(0xc00049c2d0) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:271 +0x179 ... skipping 52 lines ... Jan 28 14:46:09.859: INFO: PersistentVolumeClaim pvc-7mcbz found and phase=Bound (4.309720845s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:46:09.859[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:46:09.961[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:46:10.063[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:46:10.063[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:46:10.063[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:46:10.166[0m Jan 28 14:46:10.166: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-g9vzn" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 28 14:46:10.275: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 109.207122ms Jan 28 14:46:12.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220535369s Jan 28 14:46:14.386: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219477105s Jan 28 14:46:16.392: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.2253836s Jan 28 14:46:18.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.220299637s Jan 28 14:46:20.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220317294s ... skipping 4 lines ... Jan 28 14:46:30.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 20.220435706s Jan 28 14:46:32.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 22.221018876s Jan 28 14:46:34.386: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 24.219356971s Jan 28 14:46:36.386: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 26.219386891s Jan 28 14:46:38.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 28.220579898s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:46:38.387[0m Jan 28 14:46:38.387: INFO: Pod "azuredisk-volume-tester-g9vzn" satisfied condition "Succeeded or Failed" Jan 28 14:46:38.387: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-g9vzn" Jan 28 14:46:38.498: INFO: Pod azuredisk-volume-tester-g9vzn has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-g9vzn in namespace azuredisk-1598 [38;5;243m01/28/23 14:46:38.498[0m ... skipping 93 lines ... Jan 28 14:46:09.859: INFO: PersistentVolumeClaim pvc-7mcbz found and phase=Bound (4.309720845s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:46:09.859[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:46:09.961[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:46:10.063[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:46:10.063[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:46:10.063[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:46:10.166[0m Jan 28 14:46:10.166: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-g9vzn" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 28 14:46:10.275: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 109.207122ms Jan 28 14:46:12.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220535369s Jan 28 14:46:14.386: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.219477105s Jan 28 14:46:16.392: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.2253836s Jan 28 14:46:18.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.220299637s Jan 28 14:46:20.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220317294s ... skipping 4 lines ... Jan 28 14:46:30.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 20.220435706s Jan 28 14:46:32.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 22.221018876s Jan 28 14:46:34.386: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 24.219356971s Jan 28 14:46:36.386: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Pending", Reason="", readiness=false. Elapsed: 26.219386891s Jan 28 14:46:38.387: INFO: Pod "azuredisk-volume-tester-g9vzn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 28.220579898s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:46:38.387[0m Jan 28 14:46:38.387: INFO: Pod "azuredisk-volume-tester-g9vzn" satisfied condition "Succeeded or Failed" Jan 28 14:46:38.387: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-g9vzn" Jan 28 14:46:38.498: INFO: Pod azuredisk-volume-tester-g9vzn has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-g9vzn in namespace azuredisk-1598 [38;5;243m01/28/23 14:46:38.498[0m ... skipping 79 lines ... Jan 28 14:48:22.634: INFO: PersistentVolumeClaim pvc-ck44k found and phase=Bound (4.30831186s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:48:22.634[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:48:22.737[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:48:22.839[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:48:22.839[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:48:22.839[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:48:22.945[0m Jan 28 14:48:22.945: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-l86jq" in namespace "azuredisk-3410" to be "Succeeded or Failed" Jan 28 14:48:23.048: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 103.122756ms Jan 28 14:48:25.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206406854s Jan 28 14:48:27.150: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204966821s Jan 28 14:48:29.152: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206837044s Jan 28 14:48:31.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205774208s Jan 28 14:48:33.152: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20687074s Jan 28 14:48:35.153: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 12.207688553s Jan 28 14:48:37.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205708588s Jan 28 14:48:39.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 16.206133666s Jan 28 14:48:41.158: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 18.213142817s Jan 28 14:48:43.160: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 20.214917143s Jan 28 14:48:45.158: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.212566437s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:48:45.158[0m Jan 28 14:48:45.158: INFO: Pod "azuredisk-volume-tester-l86jq" satisfied condition "Succeeded or Failed" Jan 28 14:48:45.158: INFO: deleting Pod "azuredisk-3410"/"azuredisk-volume-tester-l86jq" Jan 28 14:48:45.268: INFO: Pod azuredisk-volume-tester-l86jq has the following logs: 100+0 records in 100+0 records out 104857600 bytes (100.0MB) copied, 0.059026 seconds, 1.7GB/s hello world ... skipping 71 lines ... Jan 28 14:48:22.634: INFO: PersistentVolumeClaim pvc-ck44k found and phase=Bound (4.30831186s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:48:22.634[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:48:22.737[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:48:22.839[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:48:22.839[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:48:22.839[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:48:22.945[0m Jan 28 14:48:22.945: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-l86jq" in namespace "azuredisk-3410" to be "Succeeded or Failed" Jan 28 14:48:23.048: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 103.122756ms Jan 28 14:48:25.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206406854s Jan 28 14:48:27.150: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204966821s Jan 28 14:48:29.152: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206837044s Jan 28 14:48:31.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205774208s Jan 28 14:48:33.152: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.20687074s Jan 28 14:48:35.153: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 12.207688553s Jan 28 14:48:37.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 14.205708588s Jan 28 14:48:39.151: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 16.206133666s Jan 28 14:48:41.158: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 18.213142817s Jan 28 14:48:43.160: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Pending", Reason="", readiness=false. Elapsed: 20.214917143s Jan 28 14:48:45.158: INFO: Pod "azuredisk-volume-tester-l86jq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.212566437s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:48:45.158[0m Jan 28 14:48:45.158: INFO: Pod "azuredisk-volume-tester-l86jq" satisfied condition "Succeeded or Failed" Jan 28 14:48:45.158: INFO: deleting Pod "azuredisk-3410"/"azuredisk-volume-tester-l86jq" Jan 28 14:48:45.268: INFO: Pod azuredisk-volume-tester-l86jq has the following logs: 100+0 records in 100+0 records out 104857600 bytes (100.0MB) copied, 0.059026 seconds, 1.7GB/s hello world ... skipping 56 lines ... Jan 28 14:50:11.840: INFO: PersistentVolumeClaim pvc-mv4vj found but phase is Pending instead of Bound. Jan 28 14:50:13.945: INFO: PersistentVolumeClaim pvc-mv4vj found and phase=Bound (4.31161032s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:50:13.945[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:50:14.048[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:50:14.151[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:50:14.151[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:50:14.255[0m Jan 28 14:50:14.255: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-tmk4d" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 28 14:50:14.357: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 101.599425ms Jan 28 14:50:16.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204761667s Jan 28 14:50:18.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204597087s Jan 28 14:50:20.459: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204382519s Jan 28 14:50:22.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205186291s Jan 28 14:50:24.459: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204333017s Jan 28 14:50:26.461: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 12.205664961s Jan 28 14:50:28.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 14.204891719s Jan 28 14:50:30.467: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Running", Reason="", readiness=false. Elapsed: 16.212287065s Jan 28 14:50:32.468: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.212677818s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:50:32.468[0m Jan 28 14:50:32.468: INFO: Pod "azuredisk-volume-tester-tmk4d" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 14:50:32.468[0m [1mSTEP:[0m Prow test resource group: capz-epg8q8 [38;5;243m01/28/23 14:50:32.469[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-1d68ca8f-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:50:32.469[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-1d68ca8f-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:50:34.816[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 14:50:34.816[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 14:50:34.816[0m ... skipping 11 lines ... Jan 28 14:50:54.652: INFO: PersistentVolumeClaim pvc-5tf9s found and phase=Bound (4.310327603s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:50:54.652[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:50:54.755[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:50:54.857[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:50:54.857[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 14:50:54.857[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:50:54.961[0m Jan 28 14:50:54.961: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gltjz" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 28 14:50:55.063: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 101.953977ms Jan 28 14:50:57.167: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205760406s Jan 28 14:50:59.170: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209247006s Jan 28 14:51:01.166: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204526647s Jan 28 14:51:03.167: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205537608s Jan 28 14:51:05.166: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205306894s Jan 28 14:51:07.165: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 12.204288815s Jan 28 14:51:09.174: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 14.212822204s Jan 28 14:51:11.173: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.212079608s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:51:11.173[0m Jan 28 14:51:11.173: INFO: Pod "azuredisk-volume-tester-gltjz" satisfied condition "Succeeded or Failed" Jan 28 14:51:11.173: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-gltjz" Jan 28 14:51:11.285: INFO: Pod azuredisk-volume-tester-gltjz has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-gltjz in namespace azuredisk-8582 [38;5;243m01/28/23 14:51:11.285[0m Jan 28 14:51:11.403: INFO: deleting PVC "azuredisk-8582"/"pvc-5tf9s" Jan 28 14:51:11.403: INFO: Deleting PersistentVolumeClaim "pvc-5tf9s" ... skipping 54 lines ... Jan 28 14:50:11.840: INFO: PersistentVolumeClaim pvc-mv4vj found but phase is Pending instead of Bound. Jan 28 14:50:13.945: INFO: PersistentVolumeClaim pvc-mv4vj found and phase=Bound (4.31161032s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:50:13.945[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:50:14.048[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:50:14.151[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:50:14.151[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:50:14.255[0m Jan 28 14:50:14.255: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-tmk4d" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 28 14:50:14.357: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 101.599425ms Jan 28 14:50:16.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 2.204761667s Jan 28 14:50:18.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204597087s Jan 28 14:50:20.459: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204382519s Jan 28 14:50:22.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205186291s Jan 28 14:50:24.459: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204333017s Jan 28 14:50:26.461: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 12.205664961s Jan 28 14:50:28.460: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Pending", Reason="", readiness=false. Elapsed: 14.204891719s Jan 28 14:50:30.467: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Running", Reason="", readiness=false. Elapsed: 16.212287065s Jan 28 14:50:32.468: INFO: Pod "azuredisk-volume-tester-tmk4d": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.212677818s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:50:32.468[0m Jan 28 14:50:32.468: INFO: Pod "azuredisk-volume-tester-tmk4d" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 14:50:32.468[0m [1mSTEP:[0m Prow test resource group: capz-epg8q8 [38;5;243m01/28/23 14:50:32.469[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-1d68ca8f-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:50:32.469[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-1d68ca8f-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:50:34.816[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 14:50:34.816[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 14:50:34.816[0m ... skipping 11 lines ... Jan 28 14:50:54.652: INFO: PersistentVolumeClaim pvc-5tf9s found and phase=Bound (4.310327603s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:50:54.652[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:50:54.755[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:50:54.857[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:50:54.857[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 14:50:54.857[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:50:54.961[0m Jan 28 14:50:54.961: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gltjz" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 28 14:50:55.063: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 101.953977ms Jan 28 14:50:57.167: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205760406s Jan 28 14:50:59.170: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209247006s Jan 28 14:51:01.166: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204526647s Jan 28 14:51:03.167: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205537608s Jan 28 14:51:05.166: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205306894s Jan 28 14:51:07.165: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 12.204288815s Jan 28 14:51:09.174: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Pending", Reason="", readiness=false. Elapsed: 14.212822204s Jan 28 14:51:11.173: INFO: Pod "azuredisk-volume-tester-gltjz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.212079608s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:51:11.173[0m Jan 28 14:51:11.173: INFO: Pod "azuredisk-volume-tester-gltjz" satisfied condition "Succeeded or Failed" Jan 28 14:51:11.173: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-gltjz" Jan 28 14:51:11.285: INFO: Pod azuredisk-volume-tester-gltjz has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-gltjz in namespace azuredisk-8582 [38;5;243m01/28/23 14:51:11.285[0m Jan 28 14:51:11.403: INFO: deleting PVC "azuredisk-8582"/"pvc-5tf9s" Jan 28 14:51:11.403: INFO: Deleting PersistentVolumeClaim "pvc-5tf9s" ... skipping 53 lines ... Jan 28 14:53:25.785: INFO: PersistentVolumeClaim pvc-9hfh4 found but phase is Pending instead of Bound. Jan 28 14:53:27.888: INFO: PersistentVolumeClaim pvc-9hfh4 found and phase=Bound (4.312501169s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:53:27.888[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:53:27.991[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:53:28.093[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:53:28.093[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:53:28.197[0m Jan 28 14:53:28.197: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-4l496" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 28 14:53:28.298: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 101.674566ms Jan 28 14:53:30.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205250151s Jan 28 14:53:32.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205498059s Jan 28 14:53:34.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205770703s Jan 28 14:53:36.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204920502s Jan 28 14:53:38.401: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204519417s Jan 28 14:53:40.401: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 12.2045293s Jan 28 14:53:42.408: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 14.211460257s Jan 28 14:53:44.408: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Running", Reason="", readiness=false. Elapsed: 16.211489748s Jan 28 14:53:46.409: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.212679914s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:53:46.409[0m Jan 28 14:53:46.410: INFO: Pod "azuredisk-volume-tester-4l496" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 14:53:46.41[0m [1mSTEP:[0m Prow test resource group: capz-epg8q8 [38;5;243m01/28/23 14:53:46.41[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-9101e76e-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:53:46.41[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-9101e76e-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:53:47.408[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 14:53:47.408[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 14:53:47.408[0m ... skipping 22 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:54:17.565[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:54:17.667[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:54:17.77[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:54:17.77[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/28/23 14:54:17.771[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 14:54:17.771[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:54:17.875[0m Jan 28 14:54:17.875: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6j74r" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 28 14:54:17.980: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 104.854017ms Jan 28 14:54:20.083: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207429944s Jan 28 14:54:22.083: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207856054s Jan 28 14:54:24.083: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207523232s Jan 28 14:54:26.082: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207109211s Jan 28 14:54:28.091: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 10.215745512s Jan 28 14:54:30.090: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.214640744s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:54:30.09[0m Jan 28 14:54:30.090: INFO: Pod "azuredisk-volume-tester-6j74r" satisfied condition "Succeeded or Failed" Jan 28 14:54:30.090: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-6j74r" Jan 28 14:54:30.207: INFO: Pod azuredisk-volume-tester-6j74r has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-6j74r in namespace azuredisk-7726 [38;5;243m01/28/23 14:54:30.207[0m Jan 28 14:54:30.324: INFO: deleting PVC "azuredisk-7726"/"pvc-5m6pc" Jan 28 14:54:30.324: INFO: Deleting PersistentVolumeClaim "pvc-5m6pc" ... skipping 57 lines ... Jan 28 14:53:25.785: INFO: PersistentVolumeClaim pvc-9hfh4 found but phase is Pending instead of Bound. Jan 28 14:53:27.888: INFO: PersistentVolumeClaim pvc-9hfh4 found and phase=Bound (4.312501169s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:53:27.888[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:53:27.991[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:53:28.093[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:53:28.093[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:53:28.197[0m Jan 28 14:53:28.197: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-4l496" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 28 14:53:28.298: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 101.674566ms Jan 28 14:53:30.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 2.205250151s Jan 28 14:53:32.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205498059s Jan 28 14:53:34.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205770703s Jan 28 14:53:36.402: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204920502s Jan 28 14:53:38.401: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204519417s Jan 28 14:53:40.401: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 12.2045293s Jan 28 14:53:42.408: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Pending", Reason="", readiness=false. Elapsed: 14.211460257s Jan 28 14:53:44.408: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Running", Reason="", readiness=false. Elapsed: 16.211489748s Jan 28 14:53:46.409: INFO: Pod "azuredisk-volume-tester-4l496": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.212679914s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:53:46.409[0m Jan 28 14:53:46.410: INFO: Pod "azuredisk-volume-tester-4l496" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 14:53:46.41[0m [1mSTEP:[0m Prow test resource group: capz-epg8q8 [38;5;243m01/28/23 14:53:46.41[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-9101e76e-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:53:46.41[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-9101e76e-9f1b-11ed-8466-3e3a72bfad70 [38;5;243m01/28/23 14:53:47.408[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 14:53:47.408[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 14:53:47.408[0m ... skipping 22 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:54:17.565[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:54:17.667[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:54:17.77[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 14:54:17.77[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/28/23 14:54:17.771[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 14:54:17.771[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:54:17.875[0m Jan 28 14:54:17.875: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6j74r" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 28 14:54:17.980: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 104.854017ms Jan 28 14:54:20.083: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207429944s Jan 28 14:54:22.083: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207856054s Jan 28 14:54:24.083: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207523232s Jan 28 14:54:26.082: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207109211s Jan 28 14:54:28.091: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Pending", Reason="", readiness=false. Elapsed: 10.215745512s Jan 28 14:54:30.090: INFO: Pod "azuredisk-volume-tester-6j74r": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.214640744s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:54:30.09[0m Jan 28 14:54:30.090: INFO: Pod "azuredisk-volume-tester-6j74r" satisfied condition "Succeeded or Failed" Jan 28 14:54:30.090: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-6j74r" Jan 28 14:54:30.207: INFO: Pod azuredisk-volume-tester-6j74r has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-6j74r in namespace azuredisk-7726 [38;5;243m01/28/23 14:54:30.207[0m Jan 28 14:54:30.324: INFO: deleting PVC "azuredisk-7726"/"pvc-5m6pc" Jan 28 14:54:30.324: INFO: Deleting PersistentVolumeClaim "pvc-5m6pc" ... skipping 80 lines ... Jan 28 14:56:53.942: INFO: PersistentVolumeClaim pvc-zxg5x found but phase is Pending instead of Bound. Jan 28 14:56:56.046: INFO: PersistentVolumeClaim pvc-zxg5x found and phase=Bound (4.309536982s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:56:56.046[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:56:56.148[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:56:56.251[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:56:56.251[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:56:56.355[0m Jan 28 14:56:56.355: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zwffx" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 28 14:56:56.464: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 108.893803ms Jan 28 14:56:58.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220044668s Jan 28 14:57:00.575: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21972782s Jan 28 14:57:02.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220782344s Jan 28 14:57:04.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.220498752s Jan 28 14:57:06.574: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.218587496s ... skipping 4 lines ... Jan 28 14:57:16.575: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 20.219384175s Jan 28 14:57:18.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 22.220190312s Jan 28 14:57:20.575: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 24.219933091s Jan 28 14:57:22.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Running", Reason="", readiness=false. Elapsed: 26.220323177s Jan 28 14:57:24.574: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 28.218901043s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:57:24.574[0m Jan 28 14:57:24.575: INFO: Pod "azuredisk-volume-tester-zwffx" satisfied condition "Succeeded or Failed" Jan 28 14:57:24.575: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-zwffx" Jan 28 14:57:24.679: INFO: Pod azuredisk-volume-tester-zwffx has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-zwffx in namespace azuredisk-3086 [38;5;243m01/28/23 14:57:24.679[0m Jan 28 14:57:24.794: INFO: deleting PVC "azuredisk-3086"/"pvc-zxg5x" Jan 28 14:57:24.794: INFO: Deleting PersistentVolumeClaim "pvc-zxg5x" ... skipping 88 lines ... Jan 28 14:56:53.942: INFO: PersistentVolumeClaim pvc-zxg5x found but phase is Pending instead of Bound. Jan 28 14:56:56.046: INFO: PersistentVolumeClaim pvc-zxg5x found and phase=Bound (4.309536982s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 14:56:56.046[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 14:56:56.148[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 14:56:56.251[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 14:56:56.251[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 14:56:56.355[0m Jan 28 14:56:56.355: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zwffx" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 28 14:56:56.464: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 108.893803ms Jan 28 14:56:58.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220044668s Jan 28 14:57:00.575: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.21972782s Jan 28 14:57:02.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.220782344s Jan 28 14:57:04.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.220498752s Jan 28 14:57:06.574: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.218587496s ... skipping 4 lines ... Jan 28 14:57:16.575: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 20.219384175s Jan 28 14:57:18.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 22.220190312s Jan 28 14:57:20.575: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Pending", Reason="", readiness=false. Elapsed: 24.219933091s Jan 28 14:57:22.576: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Running", Reason="", readiness=false. Elapsed: 26.220323177s Jan 28 14:57:24.574: INFO: Pod "azuredisk-volume-tester-zwffx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 28.218901043s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 14:57:24.574[0m Jan 28 14:57:24.575: INFO: Pod "azuredisk-volume-tester-zwffx" satisfied condition "Succeeded or Failed" Jan 28 14:57:24.575: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-zwffx" Jan 28 14:57:24.679: INFO: Pod azuredisk-volume-tester-zwffx has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-zwffx in namespace azuredisk-3086 [38;5;243m01/28/23 14:57:24.679[0m Jan 28 14:57:24.794: INFO: deleting PVC "azuredisk-3086"/"pvc-zxg5x" Jan 28 14:57:24.794: INFO: Deleting PersistentVolumeClaim "pvc-zxg5x" ... skipping 1082 lines ... Jan 28 15:21:36.764: INFO: PersistentVolumeClaim pvc-p6jwj found and phase=Bound (4.311885475s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:21:36.764[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:21:36.868[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:21:36.971[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:21:36.971[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:21:36.971[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:21:37.076[0m Jan 28 15:21:37.076: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-trd5q" in namespace "azuredisk-7577" to be "Succeeded or Failed" Jan 28 15:21:37.180: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 104.456573ms Jan 28 15:21:39.284: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.208491185s Jan 28 15:21:41.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210349214s Jan 28 15:21:43.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209765484s Jan 28 15:21:45.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209736333s Jan 28 15:21:47.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210451764s Jan 28 15:21:49.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 12.209839899s Jan 28 15:21:51.284: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 14.208116007s Jan 28 15:21:53.291: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 16.21530513s Jan 28 15:21:55.290: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.214151811s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:21:55.29[0m Jan 28 15:21:55.290: INFO: Pod "azuredisk-volume-tester-trd5q" satisfied condition "Succeeded or Failed" Jan 28 15:21:55.290: INFO: deleting Pod "azuredisk-7577"/"azuredisk-volume-tester-trd5q" Jan 28 15:21:55.403: INFO: Pod azuredisk-volume-tester-trd5q has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-trd5q in namespace azuredisk-7577 [38;5;243m01/28/23 15:21:55.403[0m Jan 28 15:21:55.527: INFO: deleting PVC "azuredisk-7577"/"pvc-p6jwj" Jan 28 15:21:55.527: INFO: Deleting PersistentVolumeClaim "pvc-p6jwj" ... skipping 39 lines ... Jan 28 15:21:36.764: INFO: PersistentVolumeClaim pvc-p6jwj found and phase=Bound (4.311885475s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:21:36.764[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:21:36.868[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:21:36.971[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:21:36.971[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:21:36.971[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:21:37.076[0m Jan 28 15:21:37.076: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-trd5q" in namespace "azuredisk-7577" to be "Succeeded or Failed" Jan 28 15:21:37.180: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 104.456573ms Jan 28 15:21:39.284: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.208491185s Jan 28 15:21:41.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210349214s Jan 28 15:21:43.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209765484s Jan 28 15:21:45.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209736333s Jan 28 15:21:47.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210451764s Jan 28 15:21:49.286: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 12.209839899s Jan 28 15:21:51.284: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 14.208116007s Jan 28 15:21:53.291: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Pending", Reason="", readiness=false. Elapsed: 16.21530513s Jan 28 15:21:55.290: INFO: Pod "azuredisk-volume-tester-trd5q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.214151811s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:21:55.29[0m Jan 28 15:21:55.290: INFO: Pod "azuredisk-volume-tester-trd5q" satisfied condition "Succeeded or Failed" Jan 28 15:21:55.290: INFO: deleting Pod "azuredisk-7577"/"azuredisk-volume-tester-trd5q" Jan 28 15:21:55.403: INFO: Pod azuredisk-volume-tester-trd5q has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-trd5q in namespace azuredisk-7577 [38;5;243m01/28/23 15:21:55.403[0m Jan 28 15:21:55.527: INFO: deleting PVC "azuredisk-7577"/"pvc-p6jwj" Jan 28 15:21:55.527: INFO: Deleting PersistentVolumeClaim "pvc-p6jwj" ... skipping 35 lines ... Jan 28 15:22:43.207: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-tlchw] to have phase Bound Jan 28 15:22:43.311: INFO: PersistentVolumeClaim pvc-tlchw found and phase=Bound (103.242137ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:22:43.311[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:22:43.413[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:22:43.517[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:22:43.517[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 15:22:43.621[0m Jan 28 15:22:43.621: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-knkpq" in namespace "azuredisk-1888" to be "Error status code" Jan 28 15:22:43.724: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 102.65964ms Jan 28 15:22:45.828: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207004253s Jan 28 15:22:47.828: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206435642s Jan 28 15:22:49.829: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207619575s Jan 28 15:22:51.829: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207608336s Jan 28 15:22:53.833: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Running", Reason="", readiness=false. Elapsed: 10.211173724s Jan 28 15:22:55.834: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Failed", Reason="", readiness=false. Elapsed: 12.212564278s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 15:22:55.834[0m Jan 28 15:22:55.834: INFO: Pod "azuredisk-volume-tester-knkpq" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 15:22:55.834[0m Jan 28 15:22:55.939: INFO: deleting Pod "azuredisk-1888"/"azuredisk-volume-tester-knkpq" Jan 28 15:22:56.044: INFO: Pod azuredisk-volume-tester-knkpq has the following logs: /bin/sh: can't create /mnt/test-1/data: Read-only file system [1mSTEP:[0m Deleting pod azuredisk-volume-tester-knkpq in namespace azuredisk-1888 [38;5;243m01/28/23 15:22:56.044[0m Jan 28 15:22:56.159: INFO: deleting PVC "azuredisk-1888"/"pvc-tlchw" ... skipping 36 lines ... Jan 28 15:22:43.207: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-tlchw] to have phase Bound Jan 28 15:22:43.311: INFO: PersistentVolumeClaim pvc-tlchw found and phase=Bound (103.242137ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:22:43.311[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:22:43.413[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:22:43.517[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:22:43.517[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 15:22:43.621[0m Jan 28 15:22:43.621: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-knkpq" in namespace "azuredisk-1888" to be "Error status code" Jan 28 15:22:43.724: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 102.65964ms Jan 28 15:22:45.828: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207004253s Jan 28 15:22:47.828: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206435642s Jan 28 15:22:49.829: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207619575s Jan 28 15:22:51.829: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207608336s Jan 28 15:22:53.833: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Running", Reason="", readiness=false. Elapsed: 10.211173724s Jan 28 15:22:55.834: INFO: Pod "azuredisk-volume-tester-knkpq": Phase="Failed", Reason="", readiness=false. Elapsed: 12.212564278s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 15:22:55.834[0m Jan 28 15:22:55.834: INFO: Pod "azuredisk-volume-tester-knkpq" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 15:22:55.834[0m Jan 28 15:22:55.939: INFO: deleting Pod "azuredisk-1888"/"azuredisk-volume-tester-knkpq" Jan 28 15:22:56.044: INFO: Pod azuredisk-volume-tester-knkpq has the following logs: /bin/sh: can't create /mnt/test-1/data: Read-only file system [1mSTEP:[0m Deleting pod azuredisk-volume-tester-knkpq in namespace azuredisk-1888 [38;5;243m01/28/23 15:22:56.044[0m Jan 28 15:22:56.159: INFO: deleting PVC "azuredisk-1888"/"pvc-tlchw" ... skipping 118 lines ... [1mSTEP:[0m Successfully provisioned a shared disk volume: "/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/single-shared-disk" [38;5;243m01/28/23 15:23:34.547[0m [1mSTEP:[0m Destroying namespace "azuredisk-417" for this suite. [38;5;243m01/28/23 15:23:35.142[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/28/23 15:23:35.247[0m Jan 28 15:23:35.247: 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/28/23 15:23:35.25[0m [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m01/28/23 15:23:35.56[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m01/28/23 15:23:35.764[0m ... skipping 2 lines ... [38;5;243m------------------------------[0m [38;5;10m• [0.824 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/28/23 15:23:35.247[0m Jan 28 15:23:35.247: 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/28/23 15:23:35.25[0m ... skipping 207 lines ... Jan 28 15:25:29.790: INFO: PersistentVolumeClaim pvc-ffsd6 found and phase=Bound (102.231406ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:25:29.79[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:25:29.893[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:25:29.995[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/28/23 15:25:30.15[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:25:38.204[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:25:38.308[0m Jan 28 15:25:38.308: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-82hzj" in namespace "azuredisk-1215" to be "Succeeded or Failed" Jan 28 15:25:38.411: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 102.449267ms Jan 28 15:25:40.515: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206863293s Jan 28 15:25:42.515: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206493503s Jan 28 15:25:44.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205428566s Jan 28 15:25:46.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205701618s Jan 28 15:25:48.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205781111s ... skipping 5 lines ... Jan 28 15:26:00.515: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 22.206613917s Jan 28 15:26:02.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 24.20519952s Jan 28 15:26:04.521: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Running", Reason="", readiness=true. Elapsed: 26.212238672s Jan 28 15:26:06.521: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Running", Reason="", readiness=false. Elapsed: 28.212551373s Jan 28 15:26:08.521: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 30.212520209s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:26:08.521[0m Jan 28 15:26:08.521: INFO: Pod "azuredisk-volume-tester-82hzj" satisfied condition "Succeeded or Failed" Jan 28 15:26:08.521: INFO: deleting Pod "azuredisk-1215"/"azuredisk-volume-tester-82hzj" Jan 28 15:26:08.639: INFO: Pod azuredisk-volume-tester-82hzj has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-82hzj in namespace azuredisk-1215 [38;5;243m01/28/23 15:26:08.639[0m Jan 28 15:26:09.089: INFO: deleting PVC "azuredisk-1215"/"pvc-ffsd6" Jan 28 15:26:09.089: INFO: Deleting PersistentVolumeClaim "pvc-ffsd6" ... skipping 36 lines ... Jan 28 15:25:29.790: INFO: PersistentVolumeClaim pvc-ffsd6 found and phase=Bound (102.231406ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:25:29.79[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:25:29.893[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:25:29.995[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/28/23 15:25:30.15[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:25:38.204[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:25:38.308[0m Jan 28 15:25:38.308: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-82hzj" in namespace "azuredisk-1215" to be "Succeeded or Failed" Jan 28 15:25:38.411: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 102.449267ms Jan 28 15:25:40.515: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206863293s Jan 28 15:25:42.515: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206493503s Jan 28 15:25:44.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.205428566s Jan 28 15:25:46.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.205701618s Jan 28 15:25:48.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.205781111s ... skipping 5 lines ... Jan 28 15:26:00.515: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 22.206613917s Jan 28 15:26:02.514: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Pending", Reason="", readiness=false. Elapsed: 24.20519952s Jan 28 15:26:04.521: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Running", Reason="", readiness=true. Elapsed: 26.212238672s Jan 28 15:26:06.521: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Running", Reason="", readiness=false. Elapsed: 28.212551373s Jan 28 15:26:08.521: INFO: Pod "azuredisk-volume-tester-82hzj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 30.212520209s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:26:08.521[0m Jan 28 15:26:08.521: INFO: Pod "azuredisk-volume-tester-82hzj" satisfied condition "Succeeded or Failed" Jan 28 15:26:08.521: INFO: deleting Pod "azuredisk-1215"/"azuredisk-volume-tester-82hzj" Jan 28 15:26:08.639: INFO: Pod azuredisk-volume-tester-82hzj has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-82hzj in namespace azuredisk-1215 [38;5;243m01/28/23 15:26:08.639[0m Jan 28 15:26:09.089: INFO: deleting PVC "azuredisk-1215"/"pvc-ffsd6" Jan 28 15:26:09.089: INFO: Deleting PersistentVolumeClaim "pvc-ffsd6" ... skipping 112 lines ... Platform: linux/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 14:20:18.543534 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test I0128 14:20:18.546288 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:20:18.554617 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 I0128 14:20:18.554636 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:20:18.554643 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:20:18.554670 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:20:18.555283 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:20:18.555326 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:20:18.555414 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0128 14:20:18.555469 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0128 14:20:18.555565 1 azure.go:1007] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0128 14:20:18.555590 1 azuredisk.go:192] disable UseInstanceMetadata for controller I0128 14:20:18.555599 1 azuredisk.go:204] cloud: AzurePublicCloud, location: uksouth, rg: capz-epg8q8, VMType: vmss, PrimaryScaleSetName: , PrimaryAvailabilitySetName: , DisableAvailabilitySetNodes: false I0128 14:20:18.562639 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount2867550771' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount2867550771: must be superuser to unmount. I0128 14:20:18.562701 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0128 14:20:18.562814 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0128 14:20:18.562827 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0128 14:20:18.562832 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0128 14:20:18.562838 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0128 14:20:18.562866 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 61 lines ... Platform: linux/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 14:20:17.352912 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test I0128 14:20:17.353526 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:20:17.368008 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 I0128 14:20:17.368027 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:20:17.368034 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:20:17.368066 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:20:17.368578 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:20:17.368620 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:20:17.368679 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0128 14:20:17.368726 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0128 14:20:17.368797 1 azure.go:1007] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0128 14:20:17.368821 1 azuredisk.go:192] disable UseInstanceMetadata for controller I0128 14:20:17.368829 1 azuredisk.go:204] cloud: AzurePublicCloud, location: uksouth, rg: capz-epg8q8, VMType: vmss, PrimaryScaleSetName: , PrimaryAvailabilitySetName: , DisableAvailabilitySetNodes: false I0128 14:20:17.374955 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount2737466840' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount2737466840: must be superuser to unmount. I0128 14:20:17.374980 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0128 14:20:17.375052 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0128 14:20:17.375063 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0128 14:20:17.375069 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0128 14:20:17.375075 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0128 14:20:17.375080 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 93 lines ... I0128 14:21:28.876492 1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-8d9db224-4fbf-4333-9523-ece3a98d0117) returned with <nil> I0128 14:21:28.876526 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.239083484 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-8d9db224-4fbf-4333-9523-ece3a98d0117" result_code="succeeded" I0128 14:21:28.876540 1 utils.go:84] GRPC response: {} I0128 14:21:35.612938 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0128 14:21:35.612961 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-52be7fd7-0762-4716-87e8-3ab472c4c37c","parameters":{"csi.storage.k8s.io/pv/name":"pvc-52be7fd7-0762-4716-87e8-3ab472c4c37c","csi.storage.k8s.io/pvc/name":"pvc-vbxgn","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}}]} I0128 14:21:35.613584 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:21:35.621006 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 I0128 14:21:35.621191 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:21:35.621248 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:21:35.621304 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:21:35.621577 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:21:35.621618 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:21:35.621658 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 49 lines ... I0128 14:22:29.007007 1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-52be7fd7-0762-4716-87e8-3ab472c4c37c) returned with <nil> I0128 14:22:29.007059 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.210442174 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-52be7fd7-0762-4716-87e8-3ab472c4c37c" result_code="succeeded" I0128 14:22:29.007075 1 utils.go:84] GRPC response: {} I0128 14:22:35.939645 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0128 14:22:35.939674 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-171599cd-fab9-4ac6-b284-068b58ce7853","parameters":{"csi.storage.k8s.io/pv/name":"pvc-171599cd-fab9-4ac6-b284-068b58ce7853","csi.storage.k8s.io/pvc/name":"pvc-84bzz","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}}]} I0128 14:22:35.940364 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:22:35.943963 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 I0128 14:22:35.944002 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:22:35.944009 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:22:35.944041 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:22:35.944478 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:22:35.944540 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:22:35.944677 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 1585 lines ... I0128 15:03:25.009535 1 controllerserver.go:317] deleting azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-4801d449-fc35-42f4-a45b-02cb93a1437d) I0128 15:03:25.033523 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 1213 I0128 15:03:30.188542 1 azure_managedDiskController.go:317] azureDisk - deleted a managed disk: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-4801d449-fc35-42f4-a45b-02cb93a1437d I0128 15:03:30.188568 1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-4801d449-fc35-42f4-a45b-02cb93a1437d) returned with <nil> I0128 15:03:30.188631 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.179048802 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-4801d449-fc35-42f4-a45b-02cb93a1437d" result_code="succeeded" I0128 15:03:30.188656 1 utils.go:84] GRPC response: {} I0128 15:06:44.936038 1 azure_armclient.go:291] Received error in WaitForAsyncOperationCompletion: 'Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded' I0128 15:06:44.936121 1 azure_armclient.go:451] Received error in WaitForAsyncOperationResult: 'Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded', no response I0128 15:06:44.936168 1 azure_diskclient.go:273] Received error in disk.put.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077, error: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded I0128 15:06:44.936289 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=239.975313452 request="azuredisk_csi_driver_controller_expand_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077" result_code="failed_csi_driver_controller_expand_volume" E0128 15:06:44.936311 1 utils.go:82] GRPC error: rpc error: code = Internal desc = failed to resize disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077) with error(Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded) I0128 15:06:44.950707 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I0128 15:06:44.950903 1 utils.go:78] GRPC request: {} I0128 15:06:44.951067 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}}}]} I0128 15:06:44.951550 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerExpandVolume I0128 15:06:44.951568 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-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077"} I0128 15:06:44.976922 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 1375 ... skipping 94 lines ... I0128 15:08:03.515947 1 controllerserver.go:317] deleting azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077) I0128 15:08:03.541853 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 1213 I0128 15:08:08.683461 1 azure_managedDiskController.go:317] azureDisk - deleted a managed disk: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077 I0128 15:08:08.683486 1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077) returned with <nil> I0128 15:08:08.683517 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.167551702 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-9c60f266-6254-4bd0-a57f-525f4276c077" result_code="succeeded" I0128 15:08:08.683617 1 utils.go:84] GRPC response: {} I0128 15:11:33.380366 1 azure_armclient.go:291] Received error in WaitForAsyncOperationCompletion: 'Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded' I0128 15:11:33.380431 1 azure_armclient.go:451] Received error in WaitForAsyncOperationResult: 'Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded', no response I0128 15:11:33.380604 1 azure_diskclient.go:273] Received error in disk.put.request: resourceID: /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-df88dad3-2603-47e1-ac24-7abd28df29e3, error: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded I0128 15:11:33.380793 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=239.959499613 request="azuredisk_csi_driver_controller_expand_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-df88dad3-2603-47e1-ac24-7abd28df29e3" result_code="failed_csi_driver_controller_expand_volume" E0128 15:11:33.380816 1 utils.go:82] GRPC error: rpc error: code = Internal desc = failed to resize disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-df88dad3-2603-47e1-ac24-7abd28df29e3) with error(Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded) I0128 15:11:33.398465 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I0128 15:11:33.398594 1 utils.go:78] GRPC request: {} I0128 15:11:33.398701 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}}}]} I0128 15:11:33.399249 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerExpandVolume I0128 15:11:33.399264 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-epg8q8/providers/Microsoft.Compute/disks/pvc-df88dad3-2603-47e1-ac24-7abd28df29e3"} I0128 15:11:33.425451 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 1375 ... skipping 516 lines ... I0128 15:25:54.970952 1 azure_controller_standard.go:236] azureDisk - update(capz-epg8q8): vm(capz-epg8q8-md-0-6vjg4) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-epg8q8/providers/microsoft.compute/disks/reattach-disk-multiple-nodes:reattach-disk-multiple-nodes]) returned with <nil> I0128 15:25:54.970993 1 azure_controller_standard.go:126] DeleteCacheForNode(capz-epg8q8-md-0-6vjg4) successfully I0128 15:25:54.971003 1 azure_controller_standard.go:272] updateCache(capz-epg8q8-md-0-6vjg4) successfully I0128 15:25:54.971013 1 azure_controller_common.go:422] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded I0128 15:25:54.971208 1 controllerserver.go:425] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-epg8q8-md-0-wb89j again I0128 15:25:54.971275 1 azure_controller_common.go:194] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-epg8q8-md-0-6vjg4, could not be attached to node(capz-epg8q8-md-0-wb89j) E0128 15:25:54.971332 1 controllerserver.go:429] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-epg8q8-md-0-wb89j failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/virtualMachines/capz-epg8q8-md-0-6vjg4), could not be attached to node(capz-epg8q8-md-0-wb89j) I0128 15:25:54.971519 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=16.5784681 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-epg8q8" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="capz-epg8q8-md-0-wb89j" result_code="failed_csi_driver_controller_publish_volume" E0128 15:25:54.971564 1 utils.go:82] GRPC error: rpc error: code = Internal desc = Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-epg8q8-md-0-wb89j failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/virtualMachines/capz-epg8q8-md-0-6vjg4), could not be attached to node(capz-epg8q8-md-0-wb89j) I0128 15:25:54.985736 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume I0128 15:25:54.985757 1 utils.go:78] GRPC request: {"node_id":"capz-epg8q8-md-0-wb89j","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-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"} I0128 15:25:55.038684 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 969 I0128 15:25:55.038922 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-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-epg8q8-md-0-wb89j (vmState Succeeded). I0128 15:25:55.038957 1 controllerserver.go:408] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-epg8q8-md-0-wb89j I0128 15:25:55.038984 1 azure_controller_common.go:255] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes lun 0 to node capz-epg8q8-md-0-wb89j, diskMap: map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-epg8q8/providers/microsoft.compute/disks/reattach-disk-multiple-nodes:%!s(*provider.AttachDiskOptions=&{None reattach-disk-multiple-nodes false 0})] ... skipping 120 lines ... Platform: linux/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 14:20:13.006321 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test I0128 14:20:13.006739 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:20:13.014818 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 I0128 14:20:13.014834 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:20:13.017544 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:20:13.017596 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:20:13.018742 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:20:13.018776 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:20:13.018849 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0128 14:20:13.018902 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0128 14:20:13.018992 1 azure.go:1007] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0128 14:20:13.019010 1 skus.go:121] NewNodeInfo: Starting to populate node and disk sku information. I0128 14:20:13.036593 1 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0128 14:20:13.039421 1 mount_linux.go:284] Detected umount with safe 'not mounted' behavior I0128 14:20:13.041561 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0128 14:20:13.041576 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0128 14:20:13.041582 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0128 14:20:13.041588 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0128 14:20:13.041593 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 151 lines ... I0128 14:24:20.038169 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:24:20.044661 1 mount_linux.go:570] Output: "" I0128 14:24:20.044683 1 mount_linux.go:529] Disk "/dev/disk/azure/scsi1/lun0" appears to be unformatted, attempting to format as type: "ext4" with options: [-F -m0 /dev/disk/azure/scsi1/lun0] I0128 14:24:20.520142 1 mount_linux.go:539] Disk successfully formatted (mkfs): ext4 - /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:20.520173 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:20.520208 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:24:20.543182 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:24:20.543253 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:24:21.090202 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:24:21.090286 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:24:22.652562 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:24:22.652703 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:24:22.653268 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:24:22.653307 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:24:22.661330 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:24:22.661352 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:24:22.673806 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:22.673837 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:24:22.720517 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:24:22.720572 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:24:23.809007 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:24:23.809027 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:24:25.356565 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:24:25.356699 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:24:25.357449 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:24:25.357666 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:24:25.362591 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:24:25.362610 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:24:25.371762 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:25.371803 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:24:25.395600 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:24:25.395886 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:24:27.459191 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:24:27.459215 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:24:29.046917 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:24:29.046955 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:24:29.047326 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:24:29.047351 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:24:29.054772 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:24:29.054792 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:24:29.067160 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:29.067206 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:24:29.091773 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:24:29.091823 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:24:33.205034 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:24:33.205056 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:24:34.782948 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:24:34.782988 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:24:34.783382 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:24:34.783411 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:24:34.790526 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:24:34.790549 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:24:34.801923 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:34.801960 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:24:34.835877 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:24:34.836086 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:24:42.879978 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:24:42.879997 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:24:44.470160 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:24:44.470239 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:24:44.470659 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:24:44.470693 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:24:44.477536 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:24:44.477557 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:24:44.489441 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:24:44.489471 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:24:44.519917 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:24:44.519965 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:25:00.616012 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:25:00.616211 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:25:02.212728 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:25:02.212770 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:25:02.213152 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:25:02.213175 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:25:02.219301 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:25:02.219326 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:25:02.230149 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:25:02.230198 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:25:02.248091 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:25:02.248135 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:25:34.265151 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:25:34.265172 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["invalid","mount","options"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-30d6646f-6737-45e5-94f6-7889b8c29201","csi.storage.k8s.io/pvc/name":"pvc-4nfrw","csi.storage.k8s.io/pvc/namespace":"azuredisk-5466","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-30d6646f-6737-45e5-94f6-7889b8c29201"} I0128 14:25:35.924415 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:25:35.924456 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType StandardSSD_LRS I0128 14:25:35.924784 1 nodeserver.go:157] NodeStageVolume: formatting /dev/disk/azure/scsi1/lun0 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount with mount options([invalid mount options]) I0128 14:25:35.924799 1 mount_linux.go:567] Attempting to determine if disk "/dev/disk/azure/scsi1/lun0" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/disk/azure/scsi1/lun0]) I0128 14:25:35.930777 1 mount_linux.go:570] Output: "DEVNAME=/dev/disk/azure/scsi1/lun0\nTYPE=ext4\n" I0128 14:25:35.930950 1 mount_linux.go:453] Checking for issues with fsck on disk: /dev/disk/azure/scsi1/lun0 I0128 14:25:35.947127 1 mount_linux.go:557] Attempting to mount disk /dev/disk/azure/scsi1/lun0 in ext4 format at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount I0128 14:25:35.947160 1 mount_linux.go:220] Mounting cmd (mount) with arguments (-t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount) E0128 14:25:35.969000 1 mount_linux.go:232] Mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. E0128 14:25:35.969054 1 utils.go:82] GRPC error: rpc error: code = Internal desc = could not format /dev/disk/azure/scsi1/lun0(lun: 0), and mount it at /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount, failed with mount failed: exit status 32 Mounting command: mount Mounting arguments: -t ext4 -o invalid,mount,options,defaults /dev/disk/azure/scsi1/lun0 /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/9f2ba767058b94fc8fdbb48352a71acbba79997f9f2cad6ee08ad23dcea8ddf0/globalmount: wrong fs type, bad option, bad superblock on /dev/sdc, missing codepage or helper program, or other error. dmesg(1) may have more information after failed mount system call. I0128 14:27:07.821964 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:27:07.821984 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc","volume_capability":{"AccessType":{"Block":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc","csi.storage.k8s.io/pvc/name":"pvc-6cngc","csi.storage.k8s.io/pvc/namespace":"azuredisk-2790","requestedsizegib":"10","skuName":"Premium_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc"} I0128 14:27:09.414538 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ I0128 14:27:09.414575 1 nodeserver.go:116] NodeStageVolume: perf optimization is disabled for /dev/disk/azure/scsi1/lun0. perfProfile none accountType Premium_LRS I0128 14:27:09.414590 1 utils.go:84] GRPC response: {} I0128 14:27:09.423147 1 utils.go:77] GRPC call: /csi.v1.Node/NodePublishVolume ... skipping 16 lines ... I0128 14:27:14.514237 1 utils.go:84] GRPC response: {} I0128 14:27:14.567625 1 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0128 14:27:14.567647 1 utils.go:78] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc"} I0128 14:27:14.567720 1 nodeserver.go:201] NodeUnstageVolume: unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc I0128 14:27:14.567743 1 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0128 14:27:14.567750 1 mount_linux.go:362] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc I0128 14:27:14.568807 1 mount_linux.go:375] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc I0128 14:27:14.568825 1 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc" I0128 14:27:14.568904 1 nodeserver.go:206] NodeUnstageVolume: unmount /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-2fff55ff-b7b9-41eb-844c-102524beb2cc successfully I0128 14:27:14.568919 1 utils.go:84] GRPC response: {} I0128 14:28:17.228382 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:28:17.228402 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/96f633f6096d55e8ab3185aba4cca29d33ae81f604c292580d3f7217f1ccf834/globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-2336c959-a993-4023-a846-6315f4752eb0","csi.storage.k8s.io/pvc/name":"pvc-tckrc","csi.storage.k8s.io/pvc/namespace":"azuredisk-5356","requestedsizegib":"10","resourceGroup":"azuredisk-csi-driver-test-f6ee384a-9f17-11ed-8466-3e3a72bfad70","skuName":"Premium_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/azuredisk-csi-driver-test-f6ee384a-9f17-11ed-8466-3e3a72bfad70/providers/Microsoft.Compute/disks/pvc-2336c959-a993-4023-a846-6315f4752eb0"} I0128 14:28:18.835768 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ ... skipping 648 lines ... I0128 14:48:44.002295 1 utils.go:84] GRPC response: {} I0128 14:48:44.096049 1 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0128 14:48:44.096212 1 utils.go:78] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc"} I0128 14:48:44.096277 1 nodeserver.go:201] NodeUnstageVolume: unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc I0128 14:48:44.096306 1 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0128 14:48:44.096377 1 mount_linux.go:362] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc I0128 14:48:44.097489 1 mount_linux.go:375] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc I0128 14:48:44.097506 1 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc" I0128 14:48:44.097592 1 nodeserver.go:206] NodeUnstageVolume: unmount /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-4a4fafb4-0956-4af7-b11e-7551884f7dcc successfully I0128 14:48:44.097653 1 utils.go:84] GRPC response: {} I0128 14:50:25.932486 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 14:50:25.932506 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/1d8ccf0b72ec52d28e3faf1f666f1323848b0f107cbcedf529e20b965e593bab/globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-fca6557b-8a10-4746-af35-0409474d041b","csi.storage.k8s.io/pvc/name":"pvc-mv4vj","csi.storage.k8s.io/pvc/namespace":"azuredisk-8582","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-fca6557b-8a10-4746-af35-0409474d041b"} I0128 14:50:27.504632 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ ... skipping 621 lines ... I0128 15:20:49.393020 1 utils.go:84] GRPC response: {} I0128 15:20:49.453926 1 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0128 15:20:49.453951 1 utils.go:78] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b"} I0128 15:20:49.454013 1 nodeserver.go:201] NodeUnstageVolume: unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b I0128 15:20:49.454044 1 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0128 15:20:49.454056 1 mount_linux.go:362] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b I0128 15:20:49.455242 1 mount_linux.go:375] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b I0128 15:20:49.455260 1 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b" I0128 15:20:49.455449 1 nodeserver.go:206] NodeUnstageVolume: unmount /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b successfully I0128 15:20:49.455468 1 utils.go:84] GRPC response: {} I0128 15:21:48.601466 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 15:21:48.601488 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/c4850cfc7fb740995dcf224cb4dc90c14076afaf93113445df304016ffa539bd/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["barrier=1","acl"]}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-385e7e4f-9e94-455e-acb2-913575b1a596","csi.storage.k8s.io/pvc/name":"pvc-p6jwj","csi.storage.k8s.io/pvc/namespace":"azuredisk-7577","device-setting/device/queue_depth":"17","device-setting/queue/max_sectors_kb":"211","device-setting/queue/nr_requests":"44","device-setting/queue/read_ahead_kb":"256","device-setting/queue/rotational":"0","device-setting/queue/scheduler":"none","device-setting/queue/wbt_lat_usec":"0","perfProfile":"advanced","requestedsizegib":"10","skuname":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-385e7e4f-9e94-455e-acb2-913575b1a596"} I0128 15:21:50.195240 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ ... skipping 102 lines ... I0128 15:24:42.448395 1 utils.go:84] GRPC response: {} I0128 15:24:42.508128 1 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0128 15:24:42.508171 1 utils.go:78] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/shared-disk-multiple-pods"} I0128 15:24:42.508425 1 nodeserver.go:201] NodeUnstageVolume: unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq I0128 15:24:42.508540 1 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0128 15:24:42.508580 1 mount_linux.go:362] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq I0128 15:24:42.509810 1 mount_linux.go:375] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq I0128 15:24:42.509826 1 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq" I0128 15:24:42.509920 1 nodeserver.go:206] NodeUnstageVolume: unmount /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq successfully I0128 15:24:42.509937 1 utils.go:84] GRPC response: {} I0128 15:27:21.577721 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 15:27:21.577742 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/e5ded7bfa9d91681436d800b1d85f68250ec6f6a9b3be96378e98233af8b08c7/globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":7}},"volume_context":{"csi.storage.k8s.io/pv/name":"pvc-3ee4f798-2343-44d7-a95a-4a54bcd356ba","csi.storage.k8s.io/pvc/name":"persistent-storage-statefulset-azuredisk-0","csi.storage.k8s.io/pvc/namespace":"default","requestedsizegib":"10","skuName":"StandardSSD_LRS","storage.kubernetes.io/csiProvisionerIdentity":"1674915618041-8081-disk.csi.azure.com"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-3ee4f798-2343-44d7-a95a-4a54bcd356ba"} I0128 15:27:23.165868 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ ... skipping 33 lines ... Platform: linux/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 14:20:03.913707 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test I0128 14:20:03.914061 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:20:03.926445 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 I0128 14:20:03.926464 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:20:03.926469 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:20:03.926497 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:20:03.927001 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:20:03.927032 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:20:03.927090 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 40 lines ... Platform: linux/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 14:20:12.960193 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test I0128 14:20:12.960599 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 14:20:12.974840 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 I0128 14:20:12.974858 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 14:20:12.974866 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 14:20:12.974890 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 14:20:12.977071 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 14:20:12.977118 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 14:20:12.977203 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0128 14:20:12.977252 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0128 14:20:12.977370 1 azure.go:1007] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0128 14:20:12.977395 1 skus.go:121] NewNodeInfo: Starting to populate node and disk sku information. I0128 14:20:12.995329 1 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0128 14:20:12.997792 1 mount_linux.go:284] Detected umount with safe 'not mounted' behavior I0128 14:20:12.997861 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0128 14:20:12.997867 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0128 14:20:12.997871 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0128 14:20:12.997876 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0128 14:20:12.997880 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 247 lines ... I0128 15:20:49.358340 1 utils.go:84] GRPC response: {} I0128 15:20:49.418560 1 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0128 15:20:49.418582 1 utils.go:78] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b"} I0128 15:20:49.418633 1 nodeserver.go:201] NodeUnstageVolume: unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b I0128 15:20:49.418657 1 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0128 15:20:49.418689 1 mount_linux.go:362] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b I0128 15:20:49.419682 1 mount_linux.go:375] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b I0128 15:20:49.419699 1 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b" I0128 15:20:49.419770 1 nodeserver.go:206] NodeUnstageVolume: unmount /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-b0093581-7f6e-4857-b10b-affd335c0e1b successfully I0128 15:20:49.419785 1 utils.go:84] GRPC response: {} I0128 15:23:49.717184 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 15:23:49.717204 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq","volume_capability":{"AccessType":{"Block":{}},"access_mode":{"mode":5}},"volume_context":{"cachingMode":"None","maxshares":"2","perfProfile":"None","requestedsizegib":"10","skuName":"Premium_LRS"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/shared-disk-multiple-pods"} I0128 15:23:51.340558 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ ... skipping 19 lines ... I0128 15:24:42.330855 1 utils.go:84] GRPC response: {} I0128 15:24:42.385207 1 utils.go:77] GRPC call: /csi.v1.Node/NodeUnstageVolume I0128 15:24:42.385228 1 utils.go:78] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq","volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-epg8q8/providers/Microsoft.Compute/disks/shared-disk-multiple-pods"} I0128 15:24:42.385278 1 nodeserver.go:201] NodeUnstageVolume: unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq I0128 15:24:42.385305 1 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0128 15:24:42.385323 1 mount_linux.go:362] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq I0128 15:24:42.386552 1 mount_linux.go:375] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq I0128 15:24:42.386568 1 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq" I0128 15:24:42.386637 1 nodeserver.go:206] NodeUnstageVolume: unmount /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/azuredisk-2954-disk.csi.azure.com-preprovisioned-pv-zp8kq successfully I0128 15:24:42.386647 1 utils.go:84] GRPC response: {} I0128 15:26:01.048805 1 utils.go:77] GRPC call: /csi.v1.Node/NodeStageVolume I0128 15:26:01.048824 1 utils.go:78] GRPC request: {"publish_context":{"LUN":"0"},"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/disk.csi.azure.com/575356d9bf8b36fb887917fd475a400c11a8625d9a0b717a901b6a58d022d90c/globalmount","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-epg8q8/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"} I0128 15:26:02.641948 1 azure_common_linux.go:185] azureDisk - found /dev/disk/azure/scsi1/lun0 by sdc under /dev/disk/azure/scsi1/ ... skipping 168 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 16960 # 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 3846 # 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 737 lines ... cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 53 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 53 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 53 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 53 cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 816.40367119 cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 53 # 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-epg8q8",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 2 cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-epg8q8",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 30795 # 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 38479 # 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 274 lines ... [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;9m[1mSummarizing 1 Failure:[0m [38;5;9m[FAIL][0m [0mDynamic Provisioning [38;5;243m[single-az] [0m[38;5;9m[1m[It] should clone a volume of larger size than the source volume and make sure the filesystem is appropriately adjusted [disk.csi.azure.com][0m[0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:823[0m [38;5;9m[1mRan 35 of 66 Specs in 4497.628 seconds[0m [38;5;9m[1mFAIL![0m -- [38;5;10m[1m34 Passed[0m | [38;5;9m[1m1 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m31 Skipped[0m [38;5;228mYou're using deprecated Ginkgo functionality:[0m [38;5;228m=============================================[0m [38;5;11mSupport for custom reporters has been removed in V2. Please read the documentation linked to below for Ginkgo's new behavior and for a migration path:[0m [1mLearn more at:[0m [38;5;14m[4mhttps://onsi.github.io/ginkgo/MIGRATING_TO_V2#removed-custom-reporters[0m [38;5;243mTo silence deprecations that can be silenced set the following environment variable:[0m [38;5;243mACK_GINKGO_DEPRECATIONS=2.4.0[0m --- FAIL: TestE2E (4497.63s) FAIL FAIL sigs.k8s.io/azuredisk-csi-driver/test/e2e 4497.704s FAIL make: *** [Makefile:261: e2e-test] Error 1 NAME STATUS ROLES AGE VERSION INTERNAL-IP EXTERNAL-IP OS-IMAGE KERNEL-VERSION CONTAINER-RUNTIME capz-epg8q8-control-plane-gz6b5 Ready control-plane 79m v1.24.6 10.0.0.4 <none> Ubuntu 20.04.5 LTS 5.15.0-1020-azure containerd://1.6.2 capz-epg8q8-md-0-6vjg4 Ready <none> 77m v1.24.6 10.1.0.5 <none> Ubuntu 20.04.5 LTS 5.15.0-1020-azure containerd://1.6.2 capz-epg8q8-md-0-wb89j Ready <none> 77m v1.24.6 10.1.0.4 <none> Ubuntu 20.04.5 LTS 5.15.0-1020-azure containerd://1.6.2 NAMESPACE NAME READY STATUS RESTARTS AGE IP NODE NOMINATED NODE READINESS GATES calico-apiserver calico-apiserver-66c75f5444-nrbr6 1/1 Running 0 78m 192.168.104.135 capz-epg8q8-control-plane-gz6b5 <none> <none> ... skipping 89 lines ... Jan 28 15:32:08.547: INFO: Creating log watcher for controller kube-system/kube-scheduler-capz-epg8q8-control-plane-gz6b5, container kube-scheduler Jan 28 15:32:08.547: INFO: Describing Pod kube-system/kube-scheduler-capz-epg8q8-control-plane-gz6b5 Jan 28 15:32:08.945: INFO: Fetching kube-system pod logs took 8.563554412s Jan 28 15:32:08.945: INFO: Dumping workload cluster default/capz-epg8q8 Azure activity log Jan 28 15:32:08.945: INFO: Creating log watcher for controller tigera-operator/tigera-operator-65d6bf4d4f-6z8qf, container tigera-operator Jan 28 15:32:08.946: INFO: Describing Pod tigera-operator/tigera-operator-65d6bf4d4f-6z8qf Jan 28 15:32:14.571: INFO: Got error while iterating over activity logs for resource group capz-epg8q8: insights.ActivityLogsClient#listNextResults: Failure responding to next results request: StatusCode=404 -- Original Error: autorest/azure: error response cannot be parsed: {"<!DOCTYPE html PUBLIC \"-//W3C//DTD XHTML 1.0 Strict//EN\" \"http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd\">\r\n<html xmlns=\"http://www.w3.org/1999/xhtml\">\r\n<head>\r\n<meta http-equiv=\"Content-Type\" content=\"text/html; charset=iso-8859-1\"/>\r\n<title>404 - File or directory not found.</title>\r\n<style type=\"text/css\">\r\n<!--\r\nbody{margin:0;font-size:.7em;font-family:Verdana, Arial, Helvetica, sans-serif;background:#EEEEEE;}\r\nfieldset{padding:0 15px 10px 15px;} \r\nh1{font-size:2.4em;margin:0;color:#FFF;}\r\nh2{font-si" '\x00' '\x00'} error: invalid character '<' looking for beginning of value Jan 28 15:32:14.571: INFO: Fetching activity logs took 5.625659336s ================ REDACTING LOGS ================ All sensitive variables are redacted cluster.cluster.x-k8s.io "capz-epg8q8" deleted /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/hack/tools/bin/kind-v0.17.0 delete cluster --name=capz || true Deleting cluster "capz" ... ... skipping 13 lines ...