kubernetes-sigs/azuredisk-csi-driver PR #1704 pull-azuredisk-csi-driver-e2e-capz-windows-2019 #1619344559739768832
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 | 1h35m |
| Revision | a093a52191d3e3d9e4045b29bef24ef84b1ddc4f |
| Refs |
1704 |
... skipping 787 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 663 lines ... type: string type: object oneOf: - required: ["persistentVolumeClaimName"] - required: ["volumeSnapshotContentName"] volumeSnapshotClassName: description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.' type: string required: - source type: object status: description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object. ... skipping 2 lines ... description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.' type: string creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown. format: date-time type: string error: description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: type: string description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$ x-kubernetes-int-or-string: true type: object required: - spec type: object ... skipping 60 lines ... type: string volumeSnapshotContentName: description: volumeSnapshotContentName specifies the name of a pre-existing VolumeSnapshotContent object representing an existing volume snapshot. This field should be set if the snapshot already exists and only needs a representation in Kubernetes. This field is immutable. type: string type: object volumeSnapshotClassName: description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.' type: string required: - source type: object status: description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object. ... skipping 2 lines ... description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.' type: string creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown. format: date-time type: string error: description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: type: string description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$ x-kubernetes-int-or-string: true type: object required: - spec type: object ... skipping 254 lines ... description: status represents the current information of a snapshot. properties: creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it indicates the creation time is unknown. The format of this field is a Unix nanoseconds time encoded as an int64. On Unix, the command `date +%s%N` returns the current time in nanoseconds since 1970-01-01 00:00:00 UTC. format: int64 type: integer error: description: error is the last observed error during snapshot creation, if any. Upon success after retry, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if a snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: description: restoreSize represents the complete size of the snapshot in bytes. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. format: int64 minimum: 0 type: integer snapshotHandle: description: snapshotHandle is the CSI "snapshot_id" of a snapshot on the underlying storage system. If not specified, it indicates that dynamic snapshot creation has either failed or it is still in progress. type: string type: object required: - spec type: object served: true ... skipping 108 lines ... description: status represents the current information of a snapshot. properties: creationTime: description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it indicates the creation time is unknown. The format of this field is a Unix nanoseconds time encoded as an int64. On Unix, the command `date +%s%N` returns the current time in nanoseconds since 1970-01-01 00:00:00 UTC. format: int64 type: integer error: description: error is the last observed error during snapshot creation, if any. Upon success after retry, this error field will be cleared. properties: message: description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.' type: string time: description: time is the timestamp when the error was encountered. format: date-time type: string type: object readyToUse: description: readyToUse indicates if a snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown. type: boolean restoreSize: description: restoreSize represents the complete size of the snapshot in bytes. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown. format: int64 minimum: 0 type: integer snapshotHandle: description: snapshotHandle is the CSI "snapshot_id" of a snapshot on the underlying storage system. If not specified, it indicates that dynamic snapshot creation has either failed or it is still in progress. type: string type: object required: - spec type: object served: true ... skipping 613 lines ... image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.6.0" args: - "-csi-address=$(ADDRESS)" - "-v=2" - "-leader-election" - "--leader-election-namespace=kube-system" - '-handle-volume-inuse-error=false' - '-feature-gates=RecoverVolumeExpansionFailure=true' - "-timeout=240s" env: - name: ADDRESS value: /csi/csi.sock volumeMounts: ... skipping 217 lines ... Jan 28 15:02:20.883: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-xvk56] to have phase Bound Jan 28 15:02:20.986: INFO: PersistentVolumeClaim pvc-xvk56 found and phase=Bound (103.074609ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:02:20.986[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:02:21.088[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:02:21.191[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:02:21.191[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 15:02:21.299[0m Jan 28 15:02:21.299: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cwwqb" in namespace "azuredisk-8081" to be "Error status code" Jan 28 15:02:21.402: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 103.379377ms Jan 28 15:02:23.505: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206072423s Jan 28 15:02:25.508: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209216257s Jan 28 15:02:27.506: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206779462s Jan 28 15:02:29.507: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.20829037s Jan 28 15:02:31.507: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208477856s ... skipping 130 lines ... Jan 28 15:06:53.516: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=true. Elapsed: 4m32.216550542s Jan 28 15:06:55.515: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=true. Elapsed: 4m34.215780778s Jan 28 15:06:57.515: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=true. Elapsed: 4m36.216360004s Jan 28 15:06:59.513: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=false. Elapsed: 4m38.214349479s Jan 28 15:07:01.515: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=false. Elapsed: 4m40.216477444s Jan 28 15:07:03.514: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=false. Elapsed: 4m42.215017748s Jan 28 15:07:05.513: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Failed", Reason="", readiness=false. Elapsed: 4m44.214014929s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 15:07:05.513[0m Jan 28 15:07:05.513: INFO: Pod "azuredisk-volume-tester-cwwqb" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 15:07:05.513[0m Jan 28 15:07:05.660: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-cwwqb" Jan 28 15:07:05.770: INFO: Pod azuredisk-volume-tester-cwwqb has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied. At line:1 char:22 + ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 80 lines ... Jan 28 15:02:20.883: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-xvk56] to have phase Bound Jan 28 15:02:20.986: INFO: PersistentVolumeClaim pvc-xvk56 found and phase=Bound (103.074609ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:02:20.986[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:02:21.088[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:02:21.191[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:02:21.191[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 15:02:21.299[0m Jan 28 15:02:21.299: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-cwwqb" in namespace "azuredisk-8081" to be "Error status code" Jan 28 15:02:21.402: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 103.379377ms Jan 28 15:02:23.505: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206072423s Jan 28 15:02:25.508: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209216257s Jan 28 15:02:27.506: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206779462s Jan 28 15:02:29.507: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.20829037s Jan 28 15:02:31.507: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208477856s ... skipping 130 lines ... Jan 28 15:06:53.516: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=true. Elapsed: 4m32.216550542s Jan 28 15:06:55.515: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=true. Elapsed: 4m34.215780778s Jan 28 15:06:57.515: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=true. Elapsed: 4m36.216360004s Jan 28 15:06:59.513: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=false. Elapsed: 4m38.214349479s Jan 28 15:07:01.515: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=false. Elapsed: 4m40.216477444s Jan 28 15:07:03.514: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Running", Reason="", readiness=false. Elapsed: 4m42.215017748s Jan 28 15:07:05.513: INFO: Pod "azuredisk-volume-tester-cwwqb": Phase="Failed", Reason="", readiness=false. Elapsed: 4m44.214014929s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 15:07:05.513[0m Jan 28 15:07:05.513: INFO: Pod "azuredisk-volume-tester-cwwqb" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 15:07:05.513[0m Jan 28 15:07:05.660: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-cwwqb" Jan 28 15:07:05.770: INFO: Pod azuredisk-volume-tester-cwwqb has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied. At line:1 char:22 + ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 138 lines ... [1mSTEP:[0m Successfully provisioned a shared disk volume: "/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/single-shared-disk" [38;5;243m01/28/23 15:07:55.128[0m [1mSTEP:[0m Destroying namespace "azuredisk-4728" for this suite. [38;5;243m01/28/23 15:08:00.855[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:08:00.963[0m Jan 28 15:08:00.963: 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:08:00.965[0m [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m01/28/23 15:08:01.278[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m01/28/23 15:08:01.482[0m ... skipping 2 lines ... [38;5;243m------------------------------[0m [38;5;10m• [0.834 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:08:00.963[0m Jan 28 15:08:00.963: 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:08:00.965[0m ... skipping 88 lines ... Jan 28 15:08:17.449: INFO: PersistentVolumeClaim pvc-pc2tw found and phase=Bound (102.966197ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:08:17.449[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:08:17.552[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:08:17.655[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/28/23 15:08:17.814[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:08:31.051[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:08:31.161[0m Jan 28 15:08:31.161: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5gsdc" in namespace "azuredisk-5194" to be "Succeeded or Failed" Jan 28 15:08:31.267: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 105.717401ms Jan 28 15:08:33.372: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210306389s Jan 28 15:08:35.373: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.211066385s Jan 28 15:08:37.372: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.210436709s Jan 28 15:08:39.372: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.210812921s Jan 28 15:08:41.374: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.212045837s ... skipping 34 lines ... Jan 28 15:09:51.379: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=true. Elapsed: 1m20.21724536s Jan 28 15:09:53.377: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=true. Elapsed: 1m22.21601171s Jan 28 15:09:55.378: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=true. Elapsed: 1m24.216048144s Jan 28 15:09:57.378: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=false. Elapsed: 1m26.216814951s Jan 28 15:09:59.379: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m28.217146618s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:09:59.379[0m Jan 28 15:09:59.379: INFO: Pod "azuredisk-volume-tester-5gsdc" satisfied condition "Succeeded or Failed" Jan 28 15:09:59.379: INFO: deleting Pod "azuredisk-5194"/"azuredisk-volume-tester-5gsdc" Jan 28 15:09:59.514: INFO: Pod azuredisk-volume-tester-5gsdc has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-5gsdc in namespace azuredisk-5194 [38;5;243m01/28/23 15:09:59.514[0m Jan 28 15:09:59.883: INFO: deleting PVC "azuredisk-5194"/"pvc-pc2tw" Jan 28 15:09:59.883: INFO: Deleting PersistentVolumeClaim "pvc-pc2tw" ... skipping 39 lines ... Jan 28 15:08:17.449: INFO: PersistentVolumeClaim pvc-pc2tw found and phase=Bound (102.966197ms) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:08:17.449[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:08:17.552[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:08:17.655[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/28/23 15:08:17.814[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:08:31.051[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:08:31.161[0m Jan 28 15:08:31.161: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5gsdc" in namespace "azuredisk-5194" to be "Succeeded or Failed" Jan 28 15:08:31.267: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 105.717401ms Jan 28 15:08:33.372: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210306389s Jan 28 15:08:35.373: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.211066385s Jan 28 15:08:37.372: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.210436709s Jan 28 15:08:39.372: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.210812921s Jan 28 15:08:41.374: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.212045837s ... skipping 34 lines ... Jan 28 15:09:51.379: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=true. Elapsed: 1m20.21724536s Jan 28 15:09:53.377: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=true. Elapsed: 1m22.21601171s Jan 28 15:09:55.378: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=true. Elapsed: 1m24.216048144s Jan 28 15:09:57.378: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Running", Reason="", readiness=false. Elapsed: 1m26.216814951s Jan 28 15:09:59.379: INFO: Pod "azuredisk-volume-tester-5gsdc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m28.217146618s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:09:59.379[0m Jan 28 15:09:59.379: INFO: Pod "azuredisk-volume-tester-5gsdc" satisfied condition "Succeeded or Failed" Jan 28 15:09:59.379: INFO: deleting Pod "azuredisk-5194"/"azuredisk-volume-tester-5gsdc" Jan 28 15:09:59.514: INFO: Pod azuredisk-volume-tester-5gsdc has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-5gsdc in namespace azuredisk-5194 [38;5;243m01/28/23 15:09:59.514[0m Jan 28 15:09:59.883: INFO: deleting PVC "azuredisk-5194"/"pvc-pc2tw" Jan 28 15:09:59.883: INFO: Deleting PersistentVolumeClaim "pvc-pc2tw" ... skipping 70 lines ... Jan 28 15:10:44.360: INFO: PersistentVolumeClaim pvc-cks82 found and phase=Bound (4.318155663s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:10:44.36[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:10:44.463[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:10:44.567[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:10:44.567[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:10:44.567[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:10:44.677[0m Jan 28 15:10:44.677: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rfvp8" in namespace "azuredisk-2888" to be "Succeeded or Failed" Jan 28 15:10:44.781: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 103.78402ms Jan 28 15:10:46.887: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209374382s Jan 28 15:10:48.888: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210607473s Jan 28 15:10:50.887: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209805234s Jan 28 15:10:52.887: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209380407s Jan 28 15:10:54.888: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210970486s ... skipping 21 lines ... Jan 28 15:11:38.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=true. Elapsed: 54.213749037s Jan 28 15:11:40.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=false. Elapsed: 56.21404181s Jan 28 15:11:42.893: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=false. Elapsed: 58.215526979s Jan 28 15:11:44.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.213787868s Jan 28 15:11:46.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m2.214006468s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:11:46.892[0m Jan 28 15:11:46.892: INFO: Pod "azuredisk-volume-tester-rfvp8" satisfied condition "Succeeded or Failed" Jan 28 15:11:46.892: INFO: deleting Pod "azuredisk-2888"/"azuredisk-volume-tester-rfvp8" Jan 28 15:11:47.019: INFO: Pod azuredisk-volume-tester-rfvp8 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-rfvp8 in namespace azuredisk-2888 [38;5;243m01/28/23 15:11:47.019[0m Jan 28 15:11:47.143: INFO: deleting PVC "azuredisk-2888"/"pvc-cks82" Jan 28 15:11:47.143: INFO: Deleting PersistentVolumeClaim "pvc-cks82" ... skipping 39 lines ... Jan 28 15:10:44.360: INFO: PersistentVolumeClaim pvc-cks82 found and phase=Bound (4.318155663s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:10:44.36[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:10:44.463[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:10:44.567[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:10:44.567[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:10:44.567[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:10:44.677[0m Jan 28 15:10:44.677: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rfvp8" in namespace "azuredisk-2888" to be "Succeeded or Failed" Jan 28 15:10:44.781: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 103.78402ms Jan 28 15:10:46.887: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.209374382s Jan 28 15:10:48.888: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210607473s Jan 28 15:10:50.887: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209805234s Jan 28 15:10:52.887: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209380407s Jan 28 15:10:54.888: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.210970486s ... skipping 21 lines ... Jan 28 15:11:38.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=true. Elapsed: 54.213749037s Jan 28 15:11:40.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=false. Elapsed: 56.21404181s Jan 28 15:11:42.893: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=false. Elapsed: 58.215526979s Jan 28 15:11:44.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.213787868s Jan 28 15:11:46.891: INFO: Pod "azuredisk-volume-tester-rfvp8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m2.214006468s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:11:46.892[0m Jan 28 15:11:46.892: INFO: Pod "azuredisk-volume-tester-rfvp8" satisfied condition "Succeeded or Failed" Jan 28 15:11:46.892: INFO: deleting Pod "azuredisk-2888"/"azuredisk-volume-tester-rfvp8" Jan 28 15:11:47.019: INFO: Pod azuredisk-volume-tester-rfvp8 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-rfvp8 in namespace azuredisk-2888 [38;5;243m01/28/23 15:11:47.019[0m Jan 28 15:11:47.143: INFO: deleting PVC "azuredisk-2888"/"pvc-cks82" Jan 28 15:11:47.143: INFO: Deleting PersistentVolumeClaim "pvc-cks82" ... skipping 37 lines ... Jan 28 15:12:32.423: INFO: PersistentVolumeClaim pvc-557h9 found but phase is Pending instead of Bound. Jan 28 15:12:34.527: INFO: PersistentVolumeClaim pvc-557h9 found and phase=Bound (4.312743505s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:12:34.527[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:12:34.63[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:12:34.734[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:12:34.735[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/28/23 15:12:34.849[0m Jan 28 15:12:34.850: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fngll" in namespace "azuredisk-156" to be "Succeeded or Failed" Jan 28 15:12:34.952: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 102.592401ms Jan 28 15:12:37.060: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210247075s Jan 28 15:12:39.058: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208503504s Jan 28 15:12:41.059: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 6.208924029s Jan 28 15:12:43.057: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207054093s Jan 28 15:12:45.057: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 10.207729908s ... skipping 22 lines ... Jan 28 15:13:31.065: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=true. Elapsed: 56.214806524s Jan 28 15:13:33.064: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=true. Elapsed: 58.214492692s Jan 28 15:13:35.063: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.213395089s Jan 28 15:13:37.064: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.214637035s Jan 28 15:13:39.064: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m4.214197355s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:13:39.064[0m Jan 28 15:13:39.064: INFO: Pod "azuredisk-volume-tester-fngll" satisfied condition "Succeeded or Failed" Jan 28 15:13:39.064: INFO: deleting Pod "azuredisk-156"/"azuredisk-volume-tester-fngll" Jan 28 15:13:39.206: INFO: Pod azuredisk-volume-tester-fngll has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-fngll in namespace azuredisk-156 [38;5;243m01/28/23 15:13:39.206[0m Jan 28 15:13:39.343: INFO: deleting PVC "azuredisk-156"/"pvc-557h9" Jan 28 15:13:39.343: INFO: Deleting PersistentVolumeClaim "pvc-557h9" ... skipping 38 lines ... Jan 28 15:12:32.423: INFO: PersistentVolumeClaim pvc-557h9 found but phase is Pending instead of Bound. Jan 28 15:12:34.527: INFO: PersistentVolumeClaim pvc-557h9 found and phase=Bound (4.312743505s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:12:34.527[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:12:34.63[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:12:34.734[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:12:34.735[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/28/23 15:12:34.849[0m Jan 28 15:12:34.850: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-fngll" in namespace "azuredisk-156" to be "Succeeded or Failed" Jan 28 15:12:34.952: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 102.592401ms Jan 28 15:12:37.060: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 2.210247075s Jan 28 15:12:39.058: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208503504s Jan 28 15:12:41.059: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 6.208924029s Jan 28 15:12:43.057: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207054093s Jan 28 15:12:45.057: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Pending", Reason="", readiness=false. Elapsed: 10.207729908s ... skipping 22 lines ... Jan 28 15:13:31.065: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=true. Elapsed: 56.214806524s Jan 28 15:13:33.064: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=true. Elapsed: 58.214492692s Jan 28 15:13:35.063: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.213395089s Jan 28 15:13:37.064: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.214637035s Jan 28 15:13:39.064: INFO: Pod "azuredisk-volume-tester-fngll": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m4.214197355s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:13:39.064[0m Jan 28 15:13:39.064: INFO: Pod "azuredisk-volume-tester-fngll" satisfied condition "Succeeded or Failed" Jan 28 15:13:39.064: INFO: deleting Pod "azuredisk-156"/"azuredisk-volume-tester-fngll" Jan 28 15:13:39.206: INFO: Pod azuredisk-volume-tester-fngll has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-fngll in namespace azuredisk-156 [38;5;243m01/28/23 15:13:39.206[0m Jan 28 15:13:39.343: INFO: deleting PVC "azuredisk-156"/"pvc-557h9" Jan 28 15:13:39.343: INFO: Deleting PersistentVolumeClaim "pvc-557h9" ... skipping 38 lines ... Jan 28 15:14:26.751: INFO: PersistentVolumeClaim pvc-pqg2n found and phase=Bound (4.31153255s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:14:26.751[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:14:26.854[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:14:26.959[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:14:26.959[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:14:26.959[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:14:27.077[0m Jan 28 15:14:27.077: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vwjqk" in namespace "azuredisk-1563" to be "Succeeded or Failed" Jan 28 15:14:27.181: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 103.241936ms Jan 28 15:14:29.286: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20833007s Jan 28 15:14:31.285: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207731439s Jan 28 15:14:33.287: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209257162s Jan 28 15:14:35.284: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.20647699s Jan 28 15:14:37.284: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206858466s ... skipping 21 lines ... Jan 28 15:15:21.304: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=true. Elapsed: 54.226183133s Jan 28 15:15:23.290: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=true. Elapsed: 56.212798574s Jan 28 15:15:25.290: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=false. Elapsed: 58.212421816s Jan 28 15:15:27.292: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.214325556s Jan 28 15:15:29.291: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m2.213488063s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:15:29.291[0m Jan 28 15:15:29.291: INFO: Pod "azuredisk-volume-tester-vwjqk" satisfied condition "Succeeded or Failed" Jan 28 15:15:29.291: INFO: deleting Pod "azuredisk-1563"/"azuredisk-volume-tester-vwjqk" Jan 28 15:15:29.423: INFO: Pod azuredisk-volume-tester-vwjqk has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vwjqk in namespace azuredisk-1563 [38;5;243m01/28/23 15:15:29.423[0m Jan 28 15:15:29.552: INFO: deleting PVC "azuredisk-1563"/"pvc-pqg2n" Jan 28 15:15:29.552: INFO: Deleting PersistentVolumeClaim "pvc-pqg2n" ... skipping 39 lines ... Jan 28 15:14:26.751: INFO: PersistentVolumeClaim pvc-pqg2n found and phase=Bound (4.31153255s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:14:26.751[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:14:26.854[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:14:26.959[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:14:26.959[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:14:26.959[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:14:27.077[0m Jan 28 15:14:27.077: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vwjqk" in namespace "azuredisk-1563" to be "Succeeded or Failed" Jan 28 15:14:27.181: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 103.241936ms Jan 28 15:14:29.286: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20833007s Jan 28 15:14:31.285: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207731439s Jan 28 15:14:33.287: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.209257162s Jan 28 15:14:35.284: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.20647699s Jan 28 15:14:37.284: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206858466s ... skipping 21 lines ... Jan 28 15:15:21.304: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=true. Elapsed: 54.226183133s Jan 28 15:15:23.290: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=true. Elapsed: 56.212798574s Jan 28 15:15:25.290: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=false. Elapsed: 58.212421816s Jan 28 15:15:27.292: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.214325556s Jan 28 15:15:29.291: INFO: Pod "azuredisk-volume-tester-vwjqk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m2.213488063s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:15:29.291[0m Jan 28 15:15:29.291: INFO: Pod "azuredisk-volume-tester-vwjqk" satisfied condition "Succeeded or Failed" Jan 28 15:15:29.291: INFO: deleting Pod "azuredisk-1563"/"azuredisk-volume-tester-vwjqk" Jan 28 15:15:29.423: INFO: Pod azuredisk-volume-tester-vwjqk has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vwjqk in namespace azuredisk-1563 [38;5;243m01/28/23 15:15:29.423[0m Jan 28 15:15:29.552: INFO: deleting PVC "azuredisk-1563"/"pvc-pqg2n" Jan 28 15:15:29.552: INFO: Deleting PersistentVolumeClaim "pvc-pqg2n" ... skipping 182 lines ... Jan 28 15:16:22.860: INFO: PersistentVolumeClaim pvc-pct48 found and phase=Bound (4.312047845s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:16:22.86[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:16:22.963[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:16:23.066[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:16:23.066[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:16:23.066[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 15:16:23.173[0m Jan 28 15:16:23.173: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-pw48k" in namespace "azuredisk-8010" to be "Error status code" Jan 28 15:16:23.276: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 102.876ms Jan 28 15:16:25.381: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.208450869s Jan 28 15:16:27.380: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207051822s Jan 28 15:16:29.382: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.2086387s Jan 28 15:16:31.382: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209348588s Jan 28 15:16:33.381: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208019711s ... skipping 19 lines ... Jan 28 15:17:13.387: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=true. Elapsed: 50.213864506s Jan 28 15:17:15.387: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=true. Elapsed: 52.213936256s Jan 28 15:17:17.386: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=true. Elapsed: 54.213081852s Jan 28 15:17:19.388: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=false. Elapsed: 56.214761582s Jan 28 15:17:21.388: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=false. Elapsed: 58.214636136s Jan 28 15:17:23.386: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.213348508s Jan 28 15:17:25.387: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Failed", Reason="", readiness=false. Elapsed: 1m2.214137733s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 15:17:25.387[0m Jan 28 15:17:25.387: INFO: Pod "azuredisk-volume-tester-pw48k" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 15:17:25.387[0m Jan 28 15:17:25.523: INFO: deleting Pod "azuredisk-8010"/"azuredisk-volume-tester-pw48k" Jan 28 15:17:25.633: INFO: Pod azuredisk-volume-tester-pw48k has the following logs: out-file : Access to the path 'C:\mnt\test-1\data' is denied. At line:1 char:1 + echo $null >> C:\mnt\test-1\data + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 48 lines ... Jan 28 15:16:22.860: INFO: PersistentVolumeClaim pvc-pct48 found and phase=Bound (4.312047845s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:16:22.86[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:16:22.963[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:16:23.066[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:16:23.066[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:16:23.066[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/28/23 15:16:23.173[0m Jan 28 15:16:23.173: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-pw48k" in namespace "azuredisk-8010" to be "Error status code" Jan 28 15:16:23.276: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 102.876ms Jan 28 15:16:25.381: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.208450869s Jan 28 15:16:27.380: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207051822s Jan 28 15:16:29.382: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.2086387s Jan 28 15:16:31.382: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.209348588s Jan 28 15:16:33.381: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208019711s ... skipping 19 lines ... Jan 28 15:17:13.387: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=true. Elapsed: 50.213864506s Jan 28 15:17:15.387: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=true. Elapsed: 52.213936256s Jan 28 15:17:17.386: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=true. Elapsed: 54.213081852s Jan 28 15:17:19.388: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=false. Elapsed: 56.214761582s Jan 28 15:17:21.388: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=false. Elapsed: 58.214636136s Jan 28 15:17:23.386: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.213348508s Jan 28 15:17:25.387: INFO: Pod "azuredisk-volume-tester-pw48k": Phase="Failed", Reason="", readiness=false. Elapsed: 1m2.214137733s [1mSTEP:[0m Saw pod failure [38;5;243m01/28/23 15:17:25.387[0m Jan 28 15:17:25.387: INFO: Pod "azuredisk-volume-tester-pw48k" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/28/23 15:17:25.387[0m Jan 28 15:17:25.523: INFO: deleting Pod "azuredisk-8010"/"azuredisk-volume-tester-pw48k" Jan 28 15:17:25.633: INFO: Pod azuredisk-volume-tester-pw48k has the following logs: out-file : Access to the path 'C:\mnt\test-1\data' is denied. At line:1 char:1 + echo $null >> C:\mnt\test-1\data + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 486 lines ... Jan 28 15:24:04.144: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-k2mkh-5d64c9676\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 28 15:24:06.143: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-k2mkh-5d64c9676\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/28/23 15:24:08.369[0m [1mSTEP:[0m check pod exec [38;5;243m01/28/23 15:24:08.583[0m Jan 28 15:24:08.584: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 15:24:10.211: INFO: rc: 1 Jan 28 15:24:10.212: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 28 15:24:12.213: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 15:24:13.361: INFO: stderr: "" Jan 28 15:24:13.361: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/28/23 15:24:13.361[0m Jan 28 15:24:13.361: INFO: Deleting pod "azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4" in namespace "azuredisk-5894" ... skipping 84 lines ... Jan 28 15:24:04.144: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-k2mkh-5d64c9676\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 28 15:24:06.143: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 28, 15, 23, 19, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-k2mkh-5d64c9676\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/28/23 15:24:08.369[0m [1mSTEP:[0m check pod exec [38;5;243m01/28/23 15:24:08.583[0m Jan 28 15:24:08.584: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 15:24:10.211: INFO: rc: 1 Jan 28 15:24:10.212: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 28 15:24:12.213: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-5894 exec azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 15:24:13.361: INFO: stderr: "" Jan 28 15:24:13.361: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/28/23 15:24:13.361[0m Jan 28 15:24:13.361: INFO: Deleting pod "azuredisk-volume-tester-k2mkh-5d64c9676-wc6j4" in namespace "azuredisk-5894" ... skipping 309 lines ... Jan 28 15:25:55.986: INFO: PersistentVolumeClaim pvc-dhtlj found and phase=Bound (4.313082542s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:25:55.986[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:25:56.094[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:25:56.197[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:25:56.197[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:25:56.198[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:25:56.306[0m Jan 28 15:25:56.306: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-k7ljn" in namespace "azuredisk-9183" to be "Succeeded or Failed" Jan 28 15:25:56.416: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 109.598941ms Jan 28 15:25:58.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219600314s Jan 28 15:26:00.537: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.231139996s Jan 28 15:26:02.525: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219519243s Jan 28 15:26:04.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.219609372s Jan 28 15:26:06.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220445097s ... skipping 31 lines ... Jan 28 15:27:10.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=true. Elapsed: 1m14.220351493s Jan 28 15:27:12.525: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.219208429s Jan 28 15:27:14.527: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=false. Elapsed: 1m18.220839484s Jan 28 15:27:16.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=false. Elapsed: 1m20.220412738s Jan 28 15:27:18.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m22.220466334s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:27:18.527[0m Jan 28 15:27:18.527: INFO: Pod "azuredisk-volume-tester-k7ljn" satisfied condition "Succeeded or Failed" Jan 28 15:27:18.527: INFO: deleting Pod "azuredisk-9183"/"azuredisk-volume-tester-k7ljn" Jan 28 15:27:18.671: INFO: Pod azuredisk-volume-tester-k7ljn has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-k7ljn in namespace azuredisk-9183 [38;5;243m01/28/23 15:27:18.671[0m ... skipping 93 lines ... Jan 28 15:25:55.986: INFO: PersistentVolumeClaim pvc-dhtlj found and phase=Bound (4.313082542s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:25:55.986[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:25:56.094[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:25:56.197[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:25:56.197[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:25:56.198[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:25:56.306[0m Jan 28 15:25:56.306: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-k7ljn" in namespace "azuredisk-9183" to be "Succeeded or Failed" Jan 28 15:25:56.416: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 109.598941ms Jan 28 15:25:58.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219600314s Jan 28 15:26:00.537: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.231139996s Jan 28 15:26:02.525: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219519243s Jan 28 15:26:04.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.219609372s Jan 28 15:26:06.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220445097s ... skipping 31 lines ... Jan 28 15:27:10.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=true. Elapsed: 1m14.220351493s Jan 28 15:27:12.525: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.219208429s Jan 28 15:27:14.527: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=false. Elapsed: 1m18.220839484s Jan 28 15:27:16.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Running", Reason="", readiness=false. Elapsed: 1m20.220412738s Jan 28 15:27:18.526: INFO: Pod "azuredisk-volume-tester-k7ljn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m22.220466334s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:27:18.527[0m Jan 28 15:27:18.527: INFO: Pod "azuredisk-volume-tester-k7ljn" satisfied condition "Succeeded or Failed" Jan 28 15:27:18.527: INFO: deleting Pod "azuredisk-9183"/"azuredisk-volume-tester-k7ljn" Jan 28 15:27:18.671: INFO: Pod azuredisk-volume-tester-k7ljn has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-k7ljn in namespace azuredisk-9183 [38;5;243m01/28/23 15:27:18.671[0m ... skipping 101 lines ... Jan 28 15:28:57.375: INFO: PersistentVolumeClaim pvc-v8hg7 found but phase is Pending instead of Bound. Jan 28 15:28:59.478: INFO: PersistentVolumeClaim pvc-v8hg7 found and phase=Bound (4.310455462s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:28:59.478[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:28:59.581[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:28:59.685[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:28:59.685[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:28:59.792[0m Jan 28 15:28:59.792: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-z6bvm" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 28 15:28:59.895: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 102.605788ms Jan 28 15:29:02.000: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207731371s Jan 28 15:29:04.000: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208188885s Jan 28 15:29:05.999: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207384561s Jan 28 15:29:07.999: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207448199s Jan 28 15:29:10.001: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208743319s ... skipping 20 lines ... Jan 28 15:29:52.004: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=true. Elapsed: 52.21234037s Jan 28 15:29:54.006: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=false. Elapsed: 54.213603297s Jan 28 15:29:56.006: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=false. Elapsed: 56.213883853s Jan 28 15:29:58.004: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=false. Elapsed: 58.212029436s Jan 28 15:30:00.005: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.213492345s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:30:00.006[0m Jan 28 15:30:00.006: INFO: Pod "azuredisk-volume-tester-z6bvm" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 15:30:00.006[0m [1mSTEP:[0m Prow test resource group: capz-3h9ayb [38;5;243m01/28/23 15:30:00.006[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-a0926225-9f20-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:30:00.007[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-a0926225-9f20-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:30:01.884[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 15:30:01.884[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 15:30:01.884[0m ... skipping 11 lines ... Jan 28 15:30:21.753: INFO: PersistentVolumeClaim pvc-ffstv found and phase=Bound (4.311139147s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:30:21.753[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:30:21.856[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:30:21.959[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:30:21.959[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 15:30:21.959[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:30:22.068[0m Jan 28 15:30:22.068: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-smjnb" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 28 15:30:22.172: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 103.12862ms Jan 28 15:30:24.275: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206774509s Jan 28 15:30:26.275: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206397864s Jan 28 15:30:28.274: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206052323s Jan 28 15:30:30.276: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207871352s Jan 28 15:30:32.275: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206967971s ... skipping 22 lines ... Jan 28 15:31:18.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=true. Elapsed: 56.212950569s Jan 28 15:31:20.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=false. Elapsed: 58.212839076s Jan 28 15:31:22.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.212491481s Jan 28 15:31:24.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.212460646s Jan 28 15:31:26.282: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m4.213566741s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:31:26.282[0m Jan 28 15:31:26.282: INFO: Pod "azuredisk-volume-tester-smjnb" satisfied condition "Succeeded or Failed" Jan 28 15:31:26.282: INFO: deleting Pod "azuredisk-1968"/"azuredisk-volume-tester-smjnb" Jan 28 15:31:26.412: INFO: Pod azuredisk-volume-tester-smjnb has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-smjnb in namespace azuredisk-1968 [38;5;243m01/28/23 15:31:26.412[0m Jan 28 15:31:26.539: INFO: deleting PVC "azuredisk-1968"/"pvc-ffstv" Jan 28 15:31:26.539: INFO: Deleting PersistentVolumeClaim "pvc-ffstv" ... skipping 53 lines ... Jan 28 15:28:57.375: INFO: PersistentVolumeClaim pvc-v8hg7 found but phase is Pending instead of Bound. Jan 28 15:28:59.478: INFO: PersistentVolumeClaim pvc-v8hg7 found and phase=Bound (4.310455462s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:28:59.478[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:28:59.581[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:28:59.685[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:28:59.685[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:28:59.792[0m Jan 28 15:28:59.792: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-z6bvm" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 28 15:28:59.895: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 102.605788ms Jan 28 15:29:02.000: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207731371s Jan 28 15:29:04.000: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208188885s Jan 28 15:29:05.999: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.207384561s Jan 28 15:29:07.999: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207448199s Jan 28 15:29:10.001: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208743319s ... skipping 20 lines ... Jan 28 15:29:52.004: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=true. Elapsed: 52.21234037s Jan 28 15:29:54.006: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=false. Elapsed: 54.213603297s Jan 28 15:29:56.006: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=false. Elapsed: 56.213883853s Jan 28 15:29:58.004: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Running", Reason="", readiness=false. Elapsed: 58.212029436s Jan 28 15:30:00.005: INFO: Pod "azuredisk-volume-tester-z6bvm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.213492345s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:30:00.006[0m Jan 28 15:30:00.006: INFO: Pod "azuredisk-volume-tester-z6bvm" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 15:30:00.006[0m [1mSTEP:[0m Prow test resource group: capz-3h9ayb [38;5;243m01/28/23 15:30:00.006[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-a0926225-9f20-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:30:00.007[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-a0926225-9f20-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:30:01.884[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 15:30:01.884[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 15:30:01.884[0m ... skipping 11 lines ... Jan 28 15:30:21.753: INFO: PersistentVolumeClaim pvc-ffstv found and phase=Bound (4.311139147s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:30:21.753[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:30:21.856[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:30:21.959[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:30:21.959[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 15:30:21.959[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:30:22.068[0m Jan 28 15:30:22.068: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-smjnb" in namespace "azuredisk-1968" to be "Succeeded or Failed" Jan 28 15:30:22.172: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 103.12862ms Jan 28 15:30:24.275: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.206774509s Jan 28 15:30:26.275: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206397864s Jan 28 15:30:28.274: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.206052323s Jan 28 15:30:30.276: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207871352s Jan 28 15:30:32.275: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.206967971s ... skipping 22 lines ... Jan 28 15:31:18.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=true. Elapsed: 56.212950569s Jan 28 15:31:20.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=false. Elapsed: 58.212839076s Jan 28 15:31:22.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.212491481s Jan 28 15:31:24.281: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.212460646s Jan 28 15:31:26.282: INFO: Pod "azuredisk-volume-tester-smjnb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m4.213566741s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:31:26.282[0m Jan 28 15:31:26.282: INFO: Pod "azuredisk-volume-tester-smjnb" satisfied condition "Succeeded or Failed" Jan 28 15:31:26.282: INFO: deleting Pod "azuredisk-1968"/"azuredisk-volume-tester-smjnb" Jan 28 15:31:26.412: INFO: Pod azuredisk-volume-tester-smjnb has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-smjnb in namespace azuredisk-1968 [38;5;243m01/28/23 15:31:26.412[0m Jan 28 15:31:26.539: INFO: deleting PVC "azuredisk-1968"/"pvc-ffstv" Jan 28 15:31:26.539: INFO: Deleting PersistentVolumeClaim "pvc-ffstv" ... skipping 52 lines ... Jan 28 15:33:49.371: INFO: PersistentVolumeClaim pvc-htxs5 found but phase is Pending instead of Bound. Jan 28 15:33:51.473: INFO: PersistentVolumeClaim pvc-htxs5 found and phase=Bound (4.319134578s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:33:51.473[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:33:51.575[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:33:51.677[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:33:51.677[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:33:51.789[0m Jan 28 15:33:51.789: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-7bd69" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 28 15:33:51.890: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 100.833714ms Jan 28 15:33:53.992: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20319789s Jan 28 15:33:55.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204147857s Jan 28 15:33:57.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204022856s Jan 28 15:33:59.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204409423s Jan 28 15:34:01.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204075049s ... skipping 19 lines ... Jan 28 15:34:42.000: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=true. Elapsed: 50.211582975s Jan 28 15:34:44.000: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=true. Elapsed: 52.210801105s Jan 28 15:34:46.001: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=true. Elapsed: 54.212058512s Jan 28 15:34:48.000: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=false. Elapsed: 56.21141102s Jan 28 15:34:49.999: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.21000572s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:34:49.999[0m Jan 28 15:34:49.999: INFO: Pod "azuredisk-volume-tester-7bd69" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 15:34:49.999[0m [1mSTEP:[0m Prow test resource group: capz-3h9ayb [38;5;243m01/28/23 15:34:50[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-4d6bd754-9f21-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:34:50[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-4d6bd754-9f21-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:34:51.156[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 15:34:51.157[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 15:34:51.157[0m ... skipping 21 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:35:19.329[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:35:19.431[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:35:19.533[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:35:19.534[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/28/23 15:35:19.534[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 15:35:19.534[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:35:19.642[0m Jan 28 15:35:19.642: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-q2976" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 28 15:35:19.747: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 105.05653ms Jan 28 15:35:21.850: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207993488s Jan 28 15:35:23.852: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209519404s Jan 28 15:35:25.851: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 6.20833675s Jan 28 15:35:27.850: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207948488s Jan 28 15:35:29.850: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208061517s ... skipping 123 lines ... Jan 28 15:39:37.858: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=true. Elapsed: 4m18.215536426s Jan 28 15:39:39.857: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=true. Elapsed: 4m20.215085798s Jan 28 15:39:41.861: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=true. Elapsed: 4m22.219264029s Jan 28 15:39:43.858: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=false. Elapsed: 4m24.215634492s Jan 28 15:39:45.858: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=false. Elapsed: 4m26.215737365s Jan 28 15:39:47.859: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=false. Elapsed: 4m28.216801065s Jan 28 15:39:49.857: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Failed", Reason="", readiness=false. Elapsed: 4m30.214426902s Jan 28 15:39:49.857: INFO: Unexpected error: <*fmt.wrapError | 0xc0008d4080>: { msg: "error while waiting for pod azuredisk-4657/azuredisk-volume-tester-q2976 to be Succeeded or Failed: pod \"azuredisk-volume-tester-q2976\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", err: <*errors.errorString | 0xc000c6e220>{ s: "pod \"azuredisk-volume-tester-q2976\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", }, } Jan 28 15:39:49.857: FAIL: error while waiting for pod azuredisk-4657/azuredisk-volume-tester-q2976 to be Succeeded or Failed: pod "azuredisk-volume-tester-q2976" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] 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.(*DynamicallyProvisionedVolumeSnapshotTest).Run(0xc000bdfd78, {0x270bd00, 0xc000ac7860}, {0x26f6f00, 0xc000c5ebe0}, 0xc0007cb8c0?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_snapshot_tester.go:142 +0x1358 ... skipping 37 lines ... Jan 28 15:42:01.426: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-4657 to be removed Jan 28 15:42:01.528: INFO: Claim "azuredisk-4657" in namespace "pvc-htxs5" doesn't exist in the system Jan 28 15:42:01.528: INFO: deleting StorageClass azuredisk-4657-disk.csi.azure.com-dynamic-sc-76krz [1mSTEP:[0m dump namespace information after failure [38;5;243m01/28/23 15:42:01.634[0m [1mSTEP:[0m Destroying namespace "azuredisk-4657" for this suite. [38;5;243m01/28/23 15:42:01.634[0m [38;5;243m------------------------------[0m [38;5;9m• [FAILED] [496.169 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 create a pod, write to its pv, take a volume snapshot, overwrite data in original pv, create another pod from the snapshot, and read unaltered original data from original pv[disk.csi.azure.com][0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:747[0m ... skipping 15 lines ... Jan 28 15:33:49.371: INFO: PersistentVolumeClaim pvc-htxs5 found but phase is Pending instead of Bound. Jan 28 15:33:51.473: INFO: PersistentVolumeClaim pvc-htxs5 found and phase=Bound (4.319134578s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:33:51.473[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:33:51.575[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:33:51.677[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:33:51.677[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:33:51.789[0m Jan 28 15:33:51.789: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-7bd69" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 28 15:33:51.890: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 100.833714ms Jan 28 15:33:53.992: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 2.20319789s Jan 28 15:33:55.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204147857s Jan 28 15:33:57.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 6.204022856s Jan 28 15:33:59.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 8.204409423s Jan 28 15:34:01.993: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Pending", Reason="", readiness=false. Elapsed: 10.204075049s ... skipping 19 lines ... Jan 28 15:34:42.000: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=true. Elapsed: 50.211582975s Jan 28 15:34:44.000: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=true. Elapsed: 52.210801105s Jan 28 15:34:46.001: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=true. Elapsed: 54.212058512s Jan 28 15:34:48.000: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Running", Reason="", readiness=false. Elapsed: 56.21141102s Jan 28 15:34:49.999: INFO: Pod "azuredisk-volume-tester-7bd69": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.21000572s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:34:49.999[0m Jan 28 15:34:49.999: INFO: Pod "azuredisk-volume-tester-7bd69" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/28/23 15:34:49.999[0m [1mSTEP:[0m Prow test resource group: capz-3h9ayb [38;5;243m01/28/23 15:34:50[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-4d6bd754-9f21-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:34:50[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-4d6bd754-9f21-11ed-b367-66cb777ae331 [38;5;243m01/28/23 15:34:51.156[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/28/23 15:34:51.157[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/28/23 15:34:51.157[0m ... skipping 21 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:35:19.329[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:35:19.431[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:35:19.533[0m [1mSTEP:[0m setting up the pod [38;5;243m01/28/23 15:35:19.534[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/28/23 15:35:19.534[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/28/23 15:35:19.534[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:35:19.642[0m Jan 28 15:35:19.642: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-q2976" in namespace "azuredisk-4657" to be "Succeeded or Failed" Jan 28 15:35:19.747: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 105.05653ms Jan 28 15:35:21.850: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 2.207993488s Jan 28 15:35:23.852: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 4.209519404s Jan 28 15:35:25.851: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 6.20833675s Jan 28 15:35:27.850: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 8.207948488s Jan 28 15:35:29.850: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Pending", Reason="", readiness=false. Elapsed: 10.208061517s ... skipping 123 lines ... Jan 28 15:39:37.858: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=true. Elapsed: 4m18.215536426s Jan 28 15:39:39.857: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=true. Elapsed: 4m20.215085798s Jan 28 15:39:41.861: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=true. Elapsed: 4m22.219264029s Jan 28 15:39:43.858: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=false. Elapsed: 4m24.215634492s Jan 28 15:39:45.858: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=false. Elapsed: 4m26.215737365s Jan 28 15:39:47.859: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Running", Reason="", readiness=false. Elapsed: 4m28.216801065s Jan 28 15:39:49.857: INFO: Pod "azuredisk-volume-tester-q2976": Phase="Failed", Reason="", readiness=false. Elapsed: 4m30.214426902s Jan 28 15:39:49.857: INFO: Unexpected error: <*fmt.wrapError | 0xc0008d4080>: { msg: "error while waiting for pod azuredisk-4657/azuredisk-volume-tester-q2976 to be Succeeded or Failed: pod \"azuredisk-volume-tester-q2976\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", err: <*errors.errorString | 0xc000c6e220>{ s: "pod \"azuredisk-volume-tester-q2976\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", }, } Jan 28 15:39:49.857: FAIL: error while waiting for pod azuredisk-4657/azuredisk-volume-tester-q2976 to be Succeeded or Failed: pod "azuredisk-volume-tester-q2976" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] 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.(*DynamicallyProvisionedVolumeSnapshotTest).Run(0xc000bdfd78, {0x270bd00, 0xc000ac7860}, {0x26f6f00, 0xc000c5ebe0}, 0xc0007cb8c0?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_snapshot_tester.go:142 +0x1358 ... skipping 38 lines ... Jan 28 15:42:01.528: INFO: Claim "azuredisk-4657" in namespace "pvc-htxs5" doesn't exist in the system Jan 28 15:42:01.528: INFO: deleting StorageClass azuredisk-4657-disk.csi.azure.com-dynamic-sc-76krz [1mSTEP:[0m dump namespace information after failure [38;5;243m01/28/23 15:42:01.634[0m [1mSTEP:[0m Destroying namespace "azuredisk-4657" for this suite. [38;5;243m01/28/23 15:42:01.634[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;9mJan 28 15:39:49.857: error while waiting for pod azuredisk-4657/azuredisk-volume-tester-q2976 to be Succeeded or Failed: pod "azuredisk-volume-tester-q2976" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:39:43 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-28 15:35:19 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.4 PodIP:192.168.29.131 PodIPs:[{IP:192.168.29.131}] StartTime:2023-01-28 15:35:19 +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 15:39:34 +0000 UTC,FinishedAt:2023-01-28 15:39:41 +0000 UTC,ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:192adcdbbcebf7000d95a0ca34422709127e20b0334e6968381a198c816c9f9f ContainerID:containerd://85f746f719c3a20512f0c7d738fc375b1e6fdad8daedcd197bb5b3961906b255 Started:0xc00094eebd}] 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(0xc00013e2d0) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:271 +0x179 ... skipping 49 lines ... Jan 28 15:42:14.997: INFO: PersistentVolumeClaim pvc-vfqdg found but phase is Pending instead of Bound. Jan 28 15:42:17.103: INFO: PersistentVolumeClaim pvc-vfqdg found and phase=Bound (4.310574018s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:42:17.103[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:42:17.205[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:42:17.307[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:42:17.307[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:42:17.416[0m Jan 28 15:42:17.416: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-s46z5" in namespace "azuredisk-1359" to be "Succeeded or Failed" Jan 28 15:42:17.526: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 109.306595ms Jan 28 15:42:19.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220930098s Jan 28 15:42:21.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.220738714s Jan 28 15:42:23.636: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219453169s Jan 28 15:42:25.636: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21936479s Jan 28 15:42:27.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220283302s ... skipping 33 lines ... Jan 28 15:43:35.638: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=true. Elapsed: 1m18.221354701s Jan 28 15:43:37.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=false. Elapsed: 1m20.220410294s Jan 28 15:43:39.638: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=false. Elapsed: 1m22.221808452s Jan 28 15:43:41.635: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=false. Elapsed: 1m24.219093496s Jan 28 15:43:43.639: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m26.222643072s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:43:43.639[0m Jan 28 15:43:43.639: INFO: Pod "azuredisk-volume-tester-s46z5" satisfied condition "Succeeded or Failed" Jan 28 15:43:43.639: INFO: deleting Pod "azuredisk-1359"/"azuredisk-volume-tester-s46z5" Jan 28 15:43:43.797: INFO: Pod azuredisk-volume-tester-s46z5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-s46z5 in namespace azuredisk-1359 [38;5;243m01/28/23 15:43:43.797[0m Jan 28 15:43:43.920: INFO: deleting PVC "azuredisk-1359"/"pvc-vfqdg" Jan 28 15:43:43.920: INFO: Deleting PersistentVolumeClaim "pvc-vfqdg" ... skipping 88 lines ... Jan 28 15:42:14.997: INFO: PersistentVolumeClaim pvc-vfqdg found but phase is Pending instead of Bound. Jan 28 15:42:17.103: INFO: PersistentVolumeClaim pvc-vfqdg found and phase=Bound (4.310574018s) [1mSTEP:[0m checking the PVC [38;5;243m01/28/23 15:42:17.103[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/28/23 15:42:17.205[0m [1mSTEP:[0m checking the PV [38;5;243m01/28/23 15:42:17.307[0m [1mSTEP:[0m deploying the pod [38;5;243m01/28/23 15:42:17.307[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/28/23 15:42:17.416[0m Jan 28 15:42:17.416: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-s46z5" in namespace "azuredisk-1359" to be "Succeeded or Failed" Jan 28 15:42:17.526: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 109.306595ms Jan 28 15:42:19.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220930098s Jan 28 15:42:21.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.220738714s Jan 28 15:42:23.636: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.219453169s Jan 28 15:42:25.636: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.21936479s Jan 28 15:42:27.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220283302s ... skipping 33 lines ... Jan 28 15:43:35.638: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=true. Elapsed: 1m18.221354701s Jan 28 15:43:37.637: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=false. Elapsed: 1m20.220410294s Jan 28 15:43:39.638: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=false. Elapsed: 1m22.221808452s Jan 28 15:43:41.635: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Running", Reason="", readiness=false. Elapsed: 1m24.219093496s Jan 28 15:43:43.639: INFO: Pod "azuredisk-volume-tester-s46z5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m26.222643072s [1mSTEP:[0m Saw pod success [38;5;243m01/28/23 15:43:43.639[0m Jan 28 15:43:43.639: INFO: Pod "azuredisk-volume-tester-s46z5" satisfied condition "Succeeded or Failed" Jan 28 15:43:43.639: INFO: deleting Pod "azuredisk-1359"/"azuredisk-volume-tester-s46z5" Jan 28 15:43:43.797: INFO: Pod azuredisk-volume-tester-s46z5 has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-s46z5 in namespace azuredisk-1359 [38;5;243m01/28/23 15:43:43.797[0m Jan 28 15:43:43.920: INFO: deleting PVC "azuredisk-1359"/"pvc-vfqdg" Jan 28 15:43:43.920: INFO: Deleting PersistentVolumeClaim "pvc-vfqdg" ... skipping 803 lines ... I0128 16:00:41.519317 41462 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0128 16:00:43.517169 41462 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/28/23 16:00:43.626[0m [1mSTEP:[0m check pod exec [38;5;243m01/28/23 16:00:43.736[0m Jan 28 16:00:43.737: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 16:00:44.951: INFO: rc: 1 Jan 28 16:00:44.951: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-qvtkr-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 28 16:00:46.952: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 16:00:48.112: INFO: rc: 1 Jan 28 16:00:48.112: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-qvtkr-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 28 16:00:48.951: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 16:00:50.094: INFO: stderr: "" Jan 28 16:00:50.094: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/28/23 16:00:50.094[0m Jan 28 16:00:50.094: INFO: Deleting pod "azuredisk-volume-tester-qvtkr-0" in namespace "azuredisk-9386" ... skipping 57 lines ... I0128 16:00:41.519317 41462 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0128 16:00:43.517169 41462 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/28/23 16:00:43.626[0m [1mSTEP:[0m check pod exec [38;5;243m01/28/23 16:00:43.736[0m Jan 28 16:00:43.737: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 16:00:44.951: INFO: rc: 1 Jan 28 16:00:44.951: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-qvtkr-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 28 16:00:46.952: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 16:00:48.112: INFO: rc: 1 Jan 28 16:00:48.112: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-qvtkr-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt: Command stdout: stderr: The system cannot find the file specified. command terminated with exit code 1 error: exit status 1. Jan 28 16:00:48.951: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-9386 exec azuredisk-volume-tester-qvtkr-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 28 16:00:50.094: INFO: stderr: "" Jan 28 16:00:50.094: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/28/23 16:00:50.094[0m Jan 28 16:00:50.094: INFO: Deleting pod "azuredisk-volume-tester-qvtkr-0" in namespace "azuredisk-9386" ... skipping 225 lines ... Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 15:01:52.179749 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test I0128 15:01:52.181571 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 15:01:52.198645 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 15 milliseconds I0128 15:01:52.199175 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 15:01:52.199195 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 15:01:52.199202 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 15:01:52.199347 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 15:01:52.203135 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 15:01:52.203292 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 15:01:52.203559 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0128 15:01:52.203727 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0128 15:01:52.204082 1 azure.go:1007] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0128 15:01:52.204113 1 azuredisk.go:192] disable UseInstanceMetadata for controller I0128 15:01:52.204123 1 azuredisk.go:204] cloud: AzurePublicCloud, location: northeurope, rg: capz-3h9ayb, VMType: vmss, PrimaryScaleSetName: , PrimaryAvailabilitySetName: , DisableAvailabilitySetNodes: false I0128 15:01:52.207581 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount1437452289' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount1437452289: must be superuser to unmount. I0128 15:01:52.207723 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0128 15:01:52.207920 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0128 15:01:52.207937 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0128 15:01:52.207941 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0128 15:01:52.207945 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0128 15:01:52.207949 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 163 lines ... I0128 15:08:51.789399 1 azure_controller_standard.go:236] azureDisk - update(capz-3h9ayb): vm(capz-3h9a-g46n2) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-3h9ayb/providers/microsoft.compute/disks/reattach-disk-multiple-nodes:reattach-disk-multiple-nodes]) returned with <nil> I0128 15:08:51.789418 1 azure_controller_standard.go:126] DeleteCacheForNode(capz-3h9a-g46n2) successfully I0128 15:08:51.789439 1 azure_controller_standard.go:272] updateCache(capz-3h9a-g46n2) successfully I0128 15:08:51.789465 1 azure_controller_common.go:422] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded I0128 15:08:51.789481 1 controllerserver.go:425] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node capz-3h9a-hf6b6 again I0128 15:08:51.789540 1 azure_controller_common.go:194] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-3h9a-g46n2, could not be attached to node(capz-3h9a-hf6b6) E0128 15:08:51.789550 1 controllerserver.go:429] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-3h9a-hf6b6 failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/virtualMachines/capz-3h9a-g46n2), could not be attached to node(capz-3h9a-hf6b6) I0128 15:08:51.789602 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=20.579448394 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-3h9ayb" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="capz-3h9a-hf6b6" result_code="failed_csi_driver_controller_publish_volume" E0128 15:08:51.789617 1 utils.go:82] GRPC error: rpc error: code = Internal desc = Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-3h9a-hf6b6 failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/virtualMachines/capz-3h9a-g46n2), could not be attached to node(capz-3h9a-hf6b6) I0128 15:08:51.797979 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume I0128 15:08:51.797992 1 utils.go:78] GRPC request: {"node_id":"capz-3h9a-hf6b6","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-3h9ayb/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"} I0128 15:08:51.831687 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 973 I0128 15:08:51.831909 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.033795488 request="disks_get" resource_group="capz-3h9ayb" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="" I0128 15:08:51.908207 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 5887 I0128 15:08:51.908897 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.076917655 request="vm_get" resource_group="capz-3h9ayb" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="" ... skipping 119 lines ... I0128 15:12:23.474736 1 utils.go:78] GRPC request: {} I0128 15:12:23.474989 1 utils.go:84] GRPC response: {"ready":{"value":true}} I0128 15:12:30.178528 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0128 15:12:30.178710 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-e83485df-757f-44fd-85bb-b1e3bf93ece8","parameters":{"csi.storage.k8s.io/pv/name":"pvc-e83485df-757f-44fd-85bb-b1e3bf93ece8","csi.storage.k8s.io/pvc/name":"pvc-557h9","csi.storage.k8s.io/pvc/namespace":"azuredisk-156","enableAsyncAttach":"false","networkAccessPolicy":"DenyAll","skuName":"Standard_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0128 15:12:30.179573 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 15:12:30.187857 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 7 milliseconds I0128 15:12:30.188077 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 15:12:30.188105 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 15:12:30.188330 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 15:12:30.188595 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 15:12:30.189154 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 15:12:30.189273 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 15:12:30.189383 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 70 lines ... I0128 15:14:15.704984 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.259417073 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-3h9ayb" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-3h9ayb/providers/Microsoft.Compute/disks/pvc-e83485df-757f-44fd-85bb-b1e3bf93ece8" result_code="succeeded" I0128 15:14:15.705010 1 utils.go:84] GRPC response: {} I0128 15:14:22.401471 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0128 15:14:22.401579 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-56175980-6888-4b92-bd69-5c3d745b6b35","parameters":{"csi.storage.k8s.io/pv/name":"pvc-56175980-6888-4b92-bd69-5c3d745b6b35","csi.storage.k8s.io/pvc/name":"pvc-pqg2n","csi.storage.k8s.io/pvc/namespace":"azuredisk-1563","enableAsyncAttach":"false","enableBursting":"true","perfProfile":"Basic","skuName":"Premium_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0128 15:14:22.402308 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0128 15:14:22.413304 1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 10 milliseconds I0128 15:14:22.414182 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 15:14:22.414805 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 15:14:22.414980 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0128 15:14:22.415243 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0128 15:14:22.415752 1 azure_auth.go:253] Using AzurePublicCloud environment I0128 15:14:22.416324 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 15:14:22.416536 1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 1984 lines ... Go Version: go1.19.5 Platform: windows/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 15:02:10.513644 4012 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test W0128 15:02:10.516984 4012 azure_disk_utils.go:230] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified. I0128 15:02:10.517684 4012 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 15:02:10.517780 4012 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0128 15:02:10.517896 4012 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0128 15:02:10.529544 4012 azure_auth.go:253] Using AzurePublicCloud environment I0128 15:02:10.530119 4012 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 15:02:10.534252 4012 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 20 lines ... I0128 15:02:11.131456 4012 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7"} I0128 15:02:11.645510 4012 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo I0128 15:02:11.645510 4012 utils.go:78] GRPC request: {} I0128 15:02:11.646137 4012 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7"} I0128 15:02:11.796645 4012 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo I0128 15:02:11.796712 4012 utils.go:78] GRPC request: {} I0128 15:02:11.826477 4012 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0128 15:02:11.836097 4012 nodeserver.go:370] NodeGetInfo: nodeName(capz-3h9a-g46n2), VM Size(Standard_D4s_v3) I0128 15:02:11.836097 4012 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8 I0128 15:02:11.836097 4012 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-3h9a-g46n2"} I0128 15:02:53.258373 4012 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0128 15:02:53.258493 4012 utils.go:78] GRPC request: {} I0128 15:02:53.258605 4012 utils.go:84] GRPC response: {"ready":{"value":true}} ... skipping 691 lines ... Go Version: go1.19.5 Platform: windows/amd64 Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0128 15:02:09.769595 5584 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7 e2e-test W0128 15:02:09.773184 5584 azure_disk_utils.go:230] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified. I0128 15:02:09.773690 5584 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0128 15:02:09.773741 5584 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0128 15:02:09.773891 5584 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0128 15:02:09.784296 5584 azure_auth.go:253] Using AzurePublicCloud environment I0128 15:02:09.785565 5584 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0128 15:02:09.791059 5584 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 20 lines ... I0128 15:02:10.476138 5584 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7"} I0128 15:02:10.604245 5584 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo I0128 15:02:10.605000 5584 utils.go:78] GRPC request: {} I0128 15:02:10.606287 5584 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.27.0-15a7100a0e7ccd86606f3f693bffc000489534a7"} I0128 15:02:11.184683 5584 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo I0128 15:02:11.184683 5584 utils.go:78] GRPC request: {} I0128 15:02:11.222369 5584 azure_instance_metadata.go:140] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found" I0128 15:02:11.222369 5584 nodeserver.go:370] NodeGetInfo: nodeName(capz-3h9a-hf6b6), VM Size(Standard_D4s_v3) I0128 15:02:11.222369 5584 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8 I0128 15:02:11.222502 5584 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-3h9a-hf6b6"} I0128 15:02:32.698573 5584 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities I0128 15:02:32.698621 5584 utils.go:78] GRPC request: {} I0128 15:02:32.698699 5584 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]} ... skipping 1859 lines ... cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 35 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 35 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 35 cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 35 cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 596.159319026 cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 35 # HELP cloudprovider_azure_op_failure_count [ALPHA] Number of failed Azure service operations # TYPE cloudprovider_azure_op_failure_count counter cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-3h9ayb",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1 # HELP disabled_metric_total [ALPHA] The count of disabled metrics. # TYPE disabled_metric_total counter disabled_metric_total 0 # HELP go_cgo_go_to_c_calls_calls_total Count of calls made from Go to C by the current process. ... skipping 67 lines ... # HELP go_gc_heap_objects_objects Number of objects, live or unswept, occupying heap memory. # TYPE go_gc_heap_objects_objects gauge go_gc_heap_objects_objects 29445 # 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 30169 # 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 272 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 create a pod, write to its pv, take a volume snapshot, overwrite data in original pv, create another pod from the snapshot, and read unaltered original data from original pv[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 24 of 66 Specs in 3822.337 seconds[0m [38;5;9m[1mFAIL![0m -- [38;5;10m[1m23 Passed[0m | [38;5;9m[1m1 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m42 Skipped[0m [38;5;228mYou're using deprecated Ginkgo functionality:[0m [38;5;228m=============================================[0m [38;5;11mSupport for custom reporters has been removed in V2. Please read the documentation linked to below for Ginkgo's new behavior and for a migration path:[0m [1mLearn more at:[0m [38;5;14m[4mhttps://onsi.github.io/ginkgo/MIGRATING_TO_V2#removed-custom-reporters[0m [38;5;243mTo silence deprecations that can be silenced set the following environment variable:[0m [38;5;243mACK_GINKGO_DEPRECATIONS=2.4.0[0m --- FAIL: TestE2E (3822.34s) FAIL FAIL sigs.k8s.io/azuredisk-csi-driver/test/e2e 3822.408s FAIL make: *** [Makefile:261: e2e-test] Error 1 NAME STATUS ROLES AGE VERSION INTERNAL-IP EXTERNAL-IP OS-IMAGE KERNEL-VERSION CONTAINER-RUNTIME capz-3h9a-g46n2 Ready <none> 66m v1.23.17-rc.0.5+a3ccd27a5da633 10.1.0.4 <none> Windows Server 2019 Datacenter 10.0.17763.3887 containerd://1.6.15 capz-3h9a-hf6b6 Ready <none> 67m v1.23.17-rc.0.5+a3ccd27a5da633 10.1.0.5 <none> Windows Server 2019 Datacenter 10.0.17763.3887 containerd://1.6.15 capz-3h9ayb-control-plane-q2qhb Ready control-plane,master 70m v1.23.17-rc.0.5+a3ccd27a5da633 10.0.0.4 <none> Ubuntu 18.04.6 LTS 5.4.0-1100-azure containerd://1.6.15 NAMESPACE NAME READY STATUS RESTARTS AGE IP NODE NOMINATED NODE READINESS GATES calico-apiserver calico-apiserver-699769956d-5vpg9 1/1 Running 0 68m 192.168.92.199 capz-3h9ayb-control-plane-q2qhb <none> <none> ... skipping 33 lines ... Jan 28 16:07:03.889: INFO: Collecting logs for Windows node capz-3h9a-g46n2 in cluster capz-3h9ayb in namespace default Jan 28 16:08:36.012: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-3h9a-g46n2 to /logs/artifacts/clusters/capz-3h9ayb/machines/capz-3h9ayb-md-win-5f85f9b94-pzd69/crashdumps.tar Jan 28 16:08:39.453: INFO: Collecting boot logs for AzureMachine capz-3h9ayb-md-win-g46n2 Failed to get logs for Machine capz-3h9ayb-md-win-5f85f9b94-pzd69, Cluster default/capz-3h9ayb: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1 Jan 28 16:08:40.795: INFO: Collecting logs for Windows node capz-3h9a-hf6b6 in cluster capz-3h9ayb in namespace default Jan 28 16:10:19.199: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-3h9a-hf6b6 to /logs/artifacts/clusters/capz-3h9ayb/machines/capz-3h9ayb-md-win-5f85f9b94-t4875/crashdumps.tar Jan 28 16:10:22.737: INFO: Collecting boot logs for AzureMachine capz-3h9ayb-md-win-hf6b6 Failed to get logs for Machine capz-3h9ayb-md-win-5f85f9b94-t4875, Cluster default/capz-3h9ayb: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1 Jan 28 16:10:24.184: INFO: Dumping workload cluster default/capz-3h9ayb kube-system pod logs Jan 28 16:10:25.259: INFO: Creating log watcher for controller calico-apiserver/calico-apiserver-699769956d-5vpg9, container calico-apiserver Jan 28 16:10:25.260: INFO: Describing Pod calico-apiserver/calico-apiserver-699769956d-5vpg9 Jan 28 16:10:25.512: INFO: Creating log watcher for controller calico-apiserver/calico-apiserver-699769956d-gfzqw, container calico-apiserver Jan 28 16:10:25.512: INFO: Describing Pod calico-apiserver/calico-apiserver-699769956d-gfzqw Jan 28 16:10:25.721: INFO: Creating log watcher for controller calico-system/calico-kube-controllers-fb49b9cf7-xh9bt, container calico-kube-controllers ... skipping 44 lines ... Jan 28 16:10:32.753: INFO: Describing Pod kube-system/metrics-server-7bdcf69694-ltbcl Jan 28 16:10:32.753: INFO: Creating log watcher for controller kube-system/metrics-server-7bdcf69694-ltbcl, container metrics-server Jan 28 16:10:33.146: INFO: Fetching kube-system pod logs took 8.962837376s Jan 28 16:10:33.146: INFO: Dumping workload cluster default/capz-3h9ayb Azure activity log Jan 28 16:10:33.146: INFO: Describing Pod tigera-operator/tigera-operator-6bbf97c9cf-j9t9t Jan 28 16:10:33.147: INFO: Creating log watcher for controller tigera-operator/tigera-operator-6bbf97c9cf-j9t9t, container tigera-operator Jan 28 16:10:41.129: INFO: Got error while iterating over activity logs for resource group capz-3h9ayb: 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 16:10:41.130: INFO: Fetching activity logs took 7.983140431s ================ REDACTING LOGS ================ All sensitive variables are redacted cluster.cluster.x-k8s.io "capz-3h9ayb" 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 12 lines ...