kubernetes-sigs/azuredisk-csi-driver PR #1704 pull-azuredisk-csi-driver-e2e-windows-containerd #1619547122401546240
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | andyzhangx: fix: switch base image to fix CVEs |
| Result | FAILURE |
| Tests | 1 failed / 14 succeeded |
| Started | |
| Elapsed | 59m48s |
| Revision | cf89f397b97f324f2562dcb6f175612715802606 |
| Refs |
1704 |
| job-version | v1.27.0-alpha.1.73+8e642d3d0deab2 |
| kubetest-version | v20230117-50d6df3625 |
| revision | v1.27.0-alpha.1.73+8e642d3d0deab2 |
error during make e2e-test: exit status 2
from junit_runner.xml
Filter through log files | View test history on testgrid
kubetest Build
kubetest Check APIReachability
kubetest Deferred TearDown
kubetest DumpClusterLogs
kubetest GetDeployer
kubetest IsUp
kubetest Prepare
kubetest TearDown
kubetest TearDown Previous
kubetest Timeout
kubetest Up
kubetest kubectl version
kubetest list nodes
kubetest test setup
... skipping 107 lines ... 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 11345 100 11345 0 0 158k 0 --:--:-- --:--:-- --:--:-- 160k Downloading https://get.helm.sh/helm-v3.11.0-linux-amd64.tar.gz Verifying checksum... Done. Preparing to install helm into /usr/local/bin helm installed into /usr/local/bin/helm docker pull k8sprow.azurecr.io/azuredisk-csi:v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df || make container-all push-manifest Error response from daemon: manifest for k8sprow.azurecr.io/azuredisk-csi:v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df not found: manifest unknown: manifest tagged by "v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df" is not found make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver' CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.driverVersion=v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=db7daf80cf6d95173fec925514d6a1d9169180df -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-29T04:13:58Z -extldflags "-static"" -mod vendor -o _output/amd64/azurediskplugin.exe ./pkg/azurediskplugin docker buildx rm container-builder || true ERROR: no builder "container-builder" found docker buildx create --use --name=container-builder container-builder # enable qemu for arm64 build # https://github.com/docker/buildx/issues/464#issuecomment-741507760 docker run --privileged --rm tonistiigi/binfmt --uninstall qemu-aarch64 Unable to find image 'tonistiigi/binfmt:latest' locally ... skipping 1117 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 673 lines ... image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.6.0" args: - "-csi-address=$(ADDRESS)" - "-v=2" - "-leader-election" - "--leader-election-namespace=kube-system" - '-handle-volume-inuse-error=false' - '-feature-gates=RecoverVolumeExpansionFailure=true' - "-timeout=240s" env: - name: ADDRESS value: /csi/csi.sock volumeMounts: ... skipping 222 lines ... Jan 29 04:20:04.803: INFO: PersistentVolumeClaim pvc-hch2p found and phase=Bound (4.089458886s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:20:04.803[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:20:04.829[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:20:04.855[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:20:04.855[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:20:04.855[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:20:04.887[0m Jan 29 04:20:04.887: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-77ddc" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 29 04:20:04.944: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 57.182916ms Jan 29 04:20:06.975: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.08781005s Jan 29 04:20:08.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.084914669s Jan 29 04:20:10.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.084336272s Jan 29 04:20:12.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.085174045s Jan 29 04:20:14.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.084340391s ... skipping 29 lines ... Jan 29 04:21:14.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.084065435s Jan 29 04:21:16.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m12.083895526s Jan 29 04:21:18.991: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m14.104268674s Jan 29 04:21:20.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.084958967s Jan 29 04:21:22.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m18.085225923s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:21:22.972[0m Jan 29 04:21:22.973: INFO: Pod "azuredisk-volume-tester-77ddc" satisfied condition "Succeeded or Failed" Jan 29 04:21:22.973: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-77ddc" Jan 29 04:21:23.040: INFO: Pod azuredisk-volume-tester-77ddc has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-77ddc in namespace azuredisk-8081 [38;5;243m01/29/23 04:21:23.04[0m Jan 29 04:21:23.091: INFO: deleting PVC "azuredisk-8081"/"pvc-hch2p" Jan 29 04:21:23.091: INFO: Deleting PersistentVolumeClaim "pvc-hch2p" ... skipping 69 lines ... Jan 29 04:20:04.803: INFO: PersistentVolumeClaim pvc-hch2p found and phase=Bound (4.089458886s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:20:04.803[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:20:04.829[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:20:04.855[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:20:04.855[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:20:04.855[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:20:04.887[0m Jan 29 04:20:04.887: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-77ddc" in namespace "azuredisk-8081" to be "Succeeded or Failed" Jan 29 04:20:04.944: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 57.182916ms Jan 29 04:20:06.975: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.08781005s Jan 29 04:20:08.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.084914669s Jan 29 04:20:10.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.084336272s Jan 29 04:20:12.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.085174045s Jan 29 04:20:14.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.084340391s ... skipping 29 lines ... Jan 29 04:21:14.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.084065435s Jan 29 04:21:16.971: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m12.083895526s Jan 29 04:21:18.991: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m14.104268674s Jan 29 04:21:20.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Running", Reason="", readiness=false. Elapsed: 1m16.084958967s Jan 29 04:21:22.972: INFO: Pod "azuredisk-volume-tester-77ddc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m18.085225923s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:21:22.972[0m Jan 29 04:21:22.973: INFO: Pod "azuredisk-volume-tester-77ddc" satisfied condition "Succeeded or Failed" Jan 29 04:21:22.973: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-77ddc" Jan 29 04:21:23.040: INFO: Pod azuredisk-volume-tester-77ddc has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-77ddc in namespace azuredisk-8081 [38;5;243m01/29/23 04:21:23.04[0m Jan 29 04:21:23.091: INFO: deleting PVC "azuredisk-8081"/"pvc-hch2p" Jan 29 04:21:23.091: INFO: Deleting PersistentVolumeClaim "pvc-hch2p" ... skipping 43 lines ... Jan 29 04:22:36.261: INFO: PersistentVolumeClaim pvc-9f945 found but phase is Pending instead of Bound. Jan 29 04:22:38.290: INFO: PersistentVolumeClaim pvc-9f945 found and phase=Bound (4.090870935s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:22:38.29[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:22:38.316[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:22:38.342[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:22:38.342[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/29/23 04:22:38.372[0m Jan 29 04:22:38.372: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-9lxsw" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 29 04:22:38.398: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 25.416888ms Jan 29 04:22:40.425: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.052625188s Jan 29 04:22:42.424: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.052096779s Jan 29 04:22:44.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.053188203s Jan 29 04:22:46.424: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.05172824s Jan 29 04:22:48.431: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.05866634s ... skipping 20 lines ... Jan 29 04:23:30.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=true. Elapsed: 52.053442451s Jan 29 04:23:32.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=true. Elapsed: 54.053156833s Jan 29 04:23:34.425: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=false. Elapsed: 56.05296627s Jan 29 04:23:36.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=false. Elapsed: 58.053971158s Jan 29 04:23:38.425: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.052737177s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:23:38.425[0m Jan 29 04:23:38.425: INFO: Pod "azuredisk-volume-tester-9lxsw" satisfied condition "Succeeded or Failed" Jan 29 04:23:38.425: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-9lxsw" Jan 29 04:23:38.493: INFO: Pod azuredisk-volume-tester-9lxsw has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-9lxsw in namespace azuredisk-2540 [38;5;243m01/29/23 04:23:38.493[0m Jan 29 04:23:38.536: INFO: deleting PVC "azuredisk-2540"/"pvc-9f945" Jan 29 04:23:38.536: INFO: Deleting PersistentVolumeClaim "pvc-9f945" ... skipping 38 lines ... Jan 29 04:22:36.261: INFO: PersistentVolumeClaim pvc-9f945 found but phase is Pending instead of Bound. Jan 29 04:22:38.290: INFO: PersistentVolumeClaim pvc-9f945 found and phase=Bound (4.090870935s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:22:38.29[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:22:38.316[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:22:38.342[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:22:38.342[0m [1mSTEP:[0m checking that the pods command exits with no error [38;5;243m01/29/23 04:22:38.372[0m Jan 29 04:22:38.372: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-9lxsw" in namespace "azuredisk-2540" to be "Succeeded or Failed" Jan 29 04:22:38.398: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 25.416888ms Jan 29 04:22:40.425: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.052625188s Jan 29 04:22:42.424: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.052096779s Jan 29 04:22:44.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.053188203s Jan 29 04:22:46.424: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.05172824s Jan 29 04:22:48.431: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.05866634s ... skipping 20 lines ... Jan 29 04:23:30.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=true. Elapsed: 52.053442451s Jan 29 04:23:32.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=true. Elapsed: 54.053156833s Jan 29 04:23:34.425: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=false. Elapsed: 56.05296627s Jan 29 04:23:36.426: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Running", Reason="", readiness=false. Elapsed: 58.053971158s Jan 29 04:23:38.425: INFO: Pod "azuredisk-volume-tester-9lxsw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m0.052737177s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:23:38.425[0m Jan 29 04:23:38.425: INFO: Pod "azuredisk-volume-tester-9lxsw" satisfied condition "Succeeded or Failed" Jan 29 04:23:38.425: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-9lxsw" Jan 29 04:23:38.493: INFO: Pod azuredisk-volume-tester-9lxsw has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-9lxsw in namespace azuredisk-2540 [38;5;243m01/29/23 04:23:38.493[0m Jan 29 04:23:38.536: INFO: deleting PVC "azuredisk-2540"/"pvc-9f945" Jan 29 04:23:38.536: INFO: Deleting PersistentVolumeClaim "pvc-9f945" ... skipping 38 lines ... Jan 29 04:24:23.523: INFO: PersistentVolumeClaim pvc-z5jlf found and phase=Bound (4.085031355s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:24:23.523[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:24:23.55[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:24:23.577[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:24:23.577[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:24:23.577[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:24:23.607[0m Jan 29 04:24:23.607: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-kxtdh" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 29 04:24:23.701: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 94.379353ms Jan 29 04:24:25.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.122698404s Jan 29 04:24:27.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.122003751s Jan 29 04:24:29.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.122006516s Jan 29 04:24:31.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.122118669s Jan 29 04:24:33.730: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.123528904s ... skipping 11 lines ... Jan 29 04:24:57.728: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=true. Elapsed: 34.121586081s Jan 29 04:24:59.732: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=true. Elapsed: 36.125072595s Jan 29 04:25:01.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=false. Elapsed: 38.122167542s Jan 29 04:25:03.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=false. Elapsed: 40.121918099s Jan 29 04:25:05.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.122063383s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:25:05.729[0m Jan 29 04:25:05.729: INFO: Pod "azuredisk-volume-tester-kxtdh" satisfied condition "Succeeded or Failed" Jan 29 04:25:05.729: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-kxtdh" Jan 29 04:25:05.806: INFO: Pod azuredisk-volume-tester-kxtdh has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-kxtdh in namespace azuredisk-4728 [38;5;243m01/29/23 04:25:05.806[0m Jan 29 04:25:05.879: INFO: deleting PVC "azuredisk-4728"/"pvc-z5jlf" Jan 29 04:25:05.879: INFO: Deleting PersistentVolumeClaim "pvc-z5jlf" ... skipping 39 lines ... Jan 29 04:24:23.523: INFO: PersistentVolumeClaim pvc-z5jlf found and phase=Bound (4.085031355s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:24:23.523[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:24:23.55[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:24:23.577[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:24:23.577[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:24:23.577[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:24:23.607[0m Jan 29 04:24:23.607: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-kxtdh" in namespace "azuredisk-4728" to be "Succeeded or Failed" Jan 29 04:24:23.701: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 94.379353ms Jan 29 04:24:25.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.122698404s Jan 29 04:24:27.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.122003751s Jan 29 04:24:29.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.122006516s Jan 29 04:24:31.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.122118669s Jan 29 04:24:33.730: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.123528904s ... skipping 11 lines ... Jan 29 04:24:57.728: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=true. Elapsed: 34.121586081s Jan 29 04:24:59.732: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=true. Elapsed: 36.125072595s Jan 29 04:25:01.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=false. Elapsed: 38.122167542s Jan 29 04:25:03.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Running", Reason="", readiness=false. Elapsed: 40.121918099s Jan 29 04:25:05.729: INFO: Pod "azuredisk-volume-tester-kxtdh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.122063383s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:25:05.729[0m Jan 29 04:25:05.729: INFO: Pod "azuredisk-volume-tester-kxtdh" satisfied condition "Succeeded or Failed" Jan 29 04:25:05.729: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-kxtdh" Jan 29 04:25:05.806: INFO: Pod azuredisk-volume-tester-kxtdh has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-kxtdh in namespace azuredisk-4728 [38;5;243m01/29/23 04:25:05.806[0m Jan 29 04:25:05.879: INFO: deleting PVC "azuredisk-4728"/"pvc-z5jlf" Jan 29 04:25:05.879: INFO: Deleting PersistentVolumeClaim "pvc-z5jlf" ... skipping 182 lines ... Jan 29 04:25:52.994: INFO: PersistentVolumeClaim pvc-xxllt found and phase=Bound (4.082070204s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:25:52.994[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:25:53.027[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:25:53.061[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:25:53.061[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:25:53.061[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/29/23 04:25:53.092[0m Jan 29 04:25:53.092: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-wddxq" in namespace "azuredisk-1353" to be "Error status code" Jan 29 04:25:53.123: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 30.768274ms Jan 29 04:25:55.151: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.059317422s Jan 29 04:25:57.152: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.059660605s Jan 29 04:25:59.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.058315843s Jan 29 04:26:01.149: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.057480935s Jan 29 04:26:03.152: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.060029623s ... skipping 9 lines ... Jan 29 04:26:23.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 30.057964469s Jan 29 04:26:25.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 32.058178384s Jan 29 04:26:27.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=true. Elapsed: 34.058190252s Jan 29 04:26:29.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=true. Elapsed: 36.05778511s Jan 29 04:26:31.153: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=false. Elapsed: 38.060619239s Jan 29 04:26:33.152: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=false. Elapsed: 40.059953663s Jan 29 04:26:35.151: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Failed", Reason="", readiness=false. Elapsed: 42.058796853s [1mSTEP:[0m Saw pod failure [38;5;243m01/29/23 04:26:35.151[0m Jan 29 04:26:35.151: INFO: Pod "azuredisk-volume-tester-wddxq" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/29/23 04:26:35.151[0m Jan 29 04:26:35.185: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-wddxq" Jan 29 04:26:35.216: INFO: Pod azuredisk-volume-tester-wddxq 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 29 04:25:52.994: INFO: PersistentVolumeClaim pvc-xxllt found and phase=Bound (4.082070204s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:25:52.994[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:25:53.027[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:25:53.061[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:25:53.061[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:25:53.061[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/29/23 04:25:53.092[0m Jan 29 04:25:53.092: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-wddxq" in namespace "azuredisk-1353" to be "Error status code" Jan 29 04:25:53.123: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 30.768274ms Jan 29 04:25:55.151: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.059317422s Jan 29 04:25:57.152: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.059660605s Jan 29 04:25:59.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.058315843s Jan 29 04:26:01.149: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.057480935s Jan 29 04:26:03.152: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.060029623s ... skipping 9 lines ... Jan 29 04:26:23.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 30.057964469s Jan 29 04:26:25.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Pending", Reason="", readiness=false. Elapsed: 32.058178384s Jan 29 04:26:27.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=true. Elapsed: 34.058190252s Jan 29 04:26:29.150: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=true. Elapsed: 36.05778511s Jan 29 04:26:31.153: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=false. Elapsed: 38.060619239s Jan 29 04:26:33.152: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Running", Reason="", readiness=false. Elapsed: 40.059953663s Jan 29 04:26:35.151: INFO: Pod "azuredisk-volume-tester-wddxq": Phase="Failed", Reason="", readiness=false. Elapsed: 42.058796853s [1mSTEP:[0m Saw pod failure [38;5;243m01/29/23 04:26:35.151[0m Jan 29 04:26:35.151: INFO: Pod "azuredisk-volume-tester-wddxq" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/29/23 04:26:35.151[0m Jan 29 04:26:35.185: INFO: deleting Pod "azuredisk-1353"/"azuredisk-volume-tester-wddxq" Jan 29 04:26:35.216: INFO: Pod azuredisk-volume-tester-wddxq 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 423 lines ... Jan 29 04:31:51.299: 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, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-44r8l-85bcd76f5d\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 29 04:31:53.299: 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, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-44r8l-85bcd76f5d\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/29/23 04:31:55.351[0m [1mSTEP:[0m check pod exec [38;5;243m01/29/23 04:31:55.404[0m Jan 29 04:31:55.404: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-156 exec azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:31:56.026: INFO: rc: 1 Jan 29 04:31:56.026: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g": error running /usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-156 exec azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g -- 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 29 04:31:58.027: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-156 exec azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:31:58.487: INFO: stderr: "" Jan 29 04:31:58.487: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/29/23 04:31:58.487[0m Jan 29 04:31:58.487: INFO: Deleting pod "azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g" in namespace "azuredisk-156" ... skipping 104 lines ... Jan 29 04:31:51.299: 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, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-44r8l-85bcd76f5d\" is progressing."}}, CollisionCount:(*int32)(nil)} Jan 29 04:31:53.299: 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, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), LastTransitionTime:time.Date(2023, time.January, 29, 4, 31, 21, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-44r8l-85bcd76f5d\" is progressing."}}, CollisionCount:(*int32)(nil)} [1mSTEP:[0m checking that the pod is running [38;5;243m01/29/23 04:31:55.351[0m [1mSTEP:[0m check pod exec [38;5;243m01/29/23 04:31:55.404[0m Jan 29 04:31:55.404: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-156 exec azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:31:56.026: INFO: rc: 1 Jan 29 04:31:56.026: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g": error running /usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-156 exec azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g -- 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 29 04:31:58.027: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-156 exec azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:31:58.487: INFO: stderr: "" Jan 29 04:31:58.487: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for deployment [38;5;243m01/29/23 04:31:58.487[0m Jan 29 04:31:58.487: INFO: Deleting pod "azuredisk-volume-tester-44r8l-85bcd76f5d-zwc7g" in namespace "azuredisk-156" ... skipping 336 lines ... Jan 29 04:34:15.757: INFO: PersistentVolumeClaim pvc-dl4hk found and phase=Bound (4.085024821s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:34:15.758[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:34:15.783[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:34:15.81[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:34:15.81[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:34:15.81[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:34:15.845[0m Jan 29 04:34:15.845: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-j694q" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 29 04:34:15.876: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 30.926887ms Jan 29 04:34:17.903: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.058172542s Jan 29 04:34:19.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.058912473s Jan 29 04:34:21.905: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.060060774s Jan 29 04:34:23.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.059056449s Jan 29 04:34:25.905: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 10.060637408s ... skipping 18 lines ... Jan 29 04:35:03.903: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=true. Elapsed: 48.058473846s Jan 29 04:35:05.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=true. Elapsed: 50.059614624s Jan 29 04:35:07.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=false. Elapsed: 52.059394079s Jan 29 04:35:09.903: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=false. Elapsed: 54.058741961s Jan 29 04:35:11.905: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 56.060556365s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:35:11.905[0m Jan 29 04:35:11.905: INFO: Pod "azuredisk-volume-tester-j694q" satisfied condition "Succeeded or Failed" Jan 29 04:35:11.905: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-j694q" Jan 29 04:35:11.978: INFO: Pod azuredisk-volume-tester-j694q has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-j694q in namespace azuredisk-1598 [38;5;243m01/29/23 04:35:11.978[0m ... skipping 88 lines ... Jan 29 04:34:15.757: INFO: PersistentVolumeClaim pvc-dl4hk found and phase=Bound (4.085024821s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:34:15.758[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:34:15.783[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:34:15.81[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:34:15.81[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:34:15.81[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:34:15.845[0m Jan 29 04:34:15.845: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-j694q" in namespace "azuredisk-1598" to be "Succeeded or Failed" Jan 29 04:34:15.876: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 30.926887ms Jan 29 04:34:17.903: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.058172542s Jan 29 04:34:19.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.058912473s Jan 29 04:34:21.905: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.060060774s Jan 29 04:34:23.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.059056449s Jan 29 04:34:25.905: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Pending", Reason="", readiness=false. Elapsed: 10.060637408s ... skipping 18 lines ... Jan 29 04:35:03.903: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=true. Elapsed: 48.058473846s Jan 29 04:35:05.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=true. Elapsed: 50.059614624s Jan 29 04:35:07.904: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=false. Elapsed: 52.059394079s Jan 29 04:35:09.903: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Running", Reason="", readiness=false. Elapsed: 54.058741961s Jan 29 04:35:11.905: INFO: Pod "azuredisk-volume-tester-j694q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 56.060556365s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:35:11.905[0m Jan 29 04:35:11.905: INFO: Pod "azuredisk-volume-tester-j694q" satisfied condition "Succeeded or Failed" Jan 29 04:35:11.905: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-j694q" Jan 29 04:35:11.978: INFO: Pod azuredisk-volume-tester-j694q has the following logs: hello world hello world hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-j694q in namespace azuredisk-1598 [38;5;243m01/29/23 04:35:11.978[0m ... skipping 96 lines ... Jan 29 04:36:20.897: INFO: PersistentVolumeClaim pvc-6nhsw found but phase is Pending instead of Bound. Jan 29 04:36:22.928: INFO: PersistentVolumeClaim pvc-6nhsw found and phase=Bound (4.083264686s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:36:22.928[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:36:22.953[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:36:22.984[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:36:22.984[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:36:23.012[0m Jan 29 04:36:23.012: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jjgfw" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 29 04:36:23.051: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 38.31566ms Jan 29 04:36:25.080: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067875657s Jan 29 04:36:27.079: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.066474773s Jan 29 04:36:29.085: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.072441353s Jan 29 04:36:31.077: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.064871501s Jan 29 04:36:33.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.065249039s ... skipping 10 lines ... Jan 29 04:36:55.079: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 32.066794514s Jan 29 04:36:57.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Running", Reason="", readiness=true. Elapsed: 34.065239408s Jan 29 04:36:59.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Running", Reason="", readiness=true. Elapsed: 36.06559478s Jan 29 04:37:01.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Running", Reason="", readiness=false. Elapsed: 38.065341905s Jan 29 04:37:03.081: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 40.06829313s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:37:03.081[0m Jan 29 04:37:03.081: INFO: Pod "azuredisk-volume-tester-jjgfw" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/29/23 04:37:03.081[0m 2023/01/29 04:37:03 Running in Prow, converting AZURE_CREDENTIALS to AZURE_CREDENTIAL_FILE 2023/01/29 04:37:03 Reading credentials file /etc/azure-cred/credentials [1mSTEP:[0m Prow test resource group: kubetest-uvfoless [38;5;243m01/29/23 04:37:03.082[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-93b7cc96-9f8e-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:37:03.082[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-93b7cc96-9f8e-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:37:03.891[0m ... skipping 13 lines ... Jan 29 04:37:23.141: INFO: PersistentVolumeClaim pvc-clgnv found and phase=Bound (4.092297272s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:37:23.141[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:37:23.167[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:37:23.193[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:37:23.193[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/29/23 04:37:23.193[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:37:23.223[0m Jan 29 04:37:23.223: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-q9x7g" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 29 04:37:23.253: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 29.587352ms Jan 29 04:37:25.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057434884s Jan 29 04:37:27.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.057888693s Jan 29 04:37:29.282: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.058910431s Jan 29 04:37:31.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.057406482s Jan 29 04:37:33.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.056839832s ... skipping 8 lines ... Jan 29 04:37:51.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 28.056465256s Jan 29 04:37:53.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 30.057503671s Jan 29 04:37:55.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 32.05642739s Jan 29 04:37:57.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Running", Reason="", readiness=true. Elapsed: 34.056887601s Jan 29 04:37:59.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Running", Reason="", readiness=true. Elapsed: 36.05700928s Jan 29 04:38:01.292: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Running", Reason="", readiness=false. Elapsed: 38.068768042s Jan 29 04:38:03.287: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Failed", Reason="", readiness=false. Elapsed: 40.0632781s Jan 29 04:38:03.287: INFO: Unexpected error: <*fmt.wrapError | 0xc000e3a340>: { msg: "error while waiting for pod azuredisk-8582/azuredisk-volume-tester-q9x7g to be Succeeded or Failed: pod \"azuredisk-volume-tester-q9x7g\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", err: <*errors.errorString | 0xc000736470>{ s: "pod \"azuredisk-volume-tester-q9x7g\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", }, } Jan 29 04:38:03.287: FAIL: error while waiting for pod azuredisk-8582/azuredisk-volume-tester-q9x7g to be Succeeded or Failed: pod "azuredisk-volume-tester-q9x7g" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] QOSClass:BestEffort EphemeralContainerStatuses:[]} Full Stack Trace sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*TestPod).WaitForSuccess(0x2253857?) /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(0xc000933d78, {0x270dda0, 0xc0000feea0}, {0x26f8fa0, 0xc000816d20}, 0xc000c818c0?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_snapshot_tester.go:142 +0x1358 ... skipping 34 lines ... Jan 29 04:40:09.593: INFO: Waiting up to 5m0s for PersistentVolumeClaim azuredisk-8582 to be removed Jan 29 04:40:09.620: INFO: Claim "azuredisk-8582" in namespace "pvc-6nhsw" doesn't exist in the system Jan 29 04:40:09.620: INFO: deleting StorageClass azuredisk-8582-disk.csi.azure.com-dynamic-sc-d2ht9 [1mSTEP:[0m dump namespace information after failure [38;5;243m01/29/23 04:40:09.65[0m [1mSTEP:[0m Destroying namespace "azuredisk-8582" for this suite. [38;5;243m01/29/23 04:40:09.651[0m [38;5;243m------------------------------[0m [38;5;9m• [FAILED] [231.343 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 and read to it, take a volume snapshot, and create another pod from the snapshot [disk.csi.azure.com][0m [38;5;243m/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:707[0m ... skipping 15 lines ... Jan 29 04:36:20.897: INFO: PersistentVolumeClaim pvc-6nhsw found but phase is Pending instead of Bound. Jan 29 04:36:22.928: INFO: PersistentVolumeClaim pvc-6nhsw found and phase=Bound (4.083264686s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:36:22.928[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:36:22.953[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:36:22.984[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:36:22.984[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:36:23.012[0m Jan 29 04:36:23.012: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jjgfw" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 29 04:36:23.051: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 38.31566ms Jan 29 04:36:25.080: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067875657s Jan 29 04:36:27.079: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.066474773s Jan 29 04:36:29.085: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.072441353s Jan 29 04:36:31.077: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.064871501s Jan 29 04:36:33.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.065249039s ... skipping 10 lines ... Jan 29 04:36:55.079: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Pending", Reason="", readiness=false. Elapsed: 32.066794514s Jan 29 04:36:57.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Running", Reason="", readiness=true. Elapsed: 34.065239408s Jan 29 04:36:59.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Running", Reason="", readiness=true. Elapsed: 36.06559478s Jan 29 04:37:01.078: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Running", Reason="", readiness=false. Elapsed: 38.065341905s Jan 29 04:37:03.081: INFO: Pod "azuredisk-volume-tester-jjgfw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 40.06829313s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:37:03.081[0m Jan 29 04:37:03.081: INFO: Pod "azuredisk-volume-tester-jjgfw" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/29/23 04:37:03.081[0m [1mSTEP:[0m Prow test resource group: kubetest-uvfoless [38;5;243m01/29/23 04:37:03.082[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-93b7cc96-9f8e-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:37:03.082[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-93b7cc96-9f8e-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:37:03.891[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/29/23 04:37:03.891[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/29/23 04:37:03.891[0m ... skipping 11 lines ... Jan 29 04:37:23.141: INFO: PersistentVolumeClaim pvc-clgnv found and phase=Bound (4.092297272s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:37:23.141[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:37:23.167[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:37:23.193[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:37:23.193[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/29/23 04:37:23.193[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:37:23.223[0m Jan 29 04:37:23.223: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-q9x7g" in namespace "azuredisk-8582" to be "Succeeded or Failed" Jan 29 04:37:23.253: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 29.587352ms Jan 29 04:37:25.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057434884s Jan 29 04:37:27.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.057888693s Jan 29 04:37:29.282: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.058910431s Jan 29 04:37:31.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.057406482s Jan 29 04:37:33.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.056839832s ... skipping 8 lines ... Jan 29 04:37:51.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 28.056465256s Jan 29 04:37:53.281: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 30.057503671s Jan 29 04:37:55.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Pending", Reason="", readiness=false. Elapsed: 32.05642739s Jan 29 04:37:57.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Running", Reason="", readiness=true. Elapsed: 34.056887601s Jan 29 04:37:59.280: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Running", Reason="", readiness=true. Elapsed: 36.05700928s Jan 29 04:38:01.292: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Running", Reason="", readiness=false. Elapsed: 38.068768042s Jan 29 04:38:03.287: INFO: Pod "azuredisk-volume-tester-q9x7g": Phase="Failed", Reason="", readiness=false. Elapsed: 40.0632781s Jan 29 04:38:03.287: INFO: Unexpected error: <*fmt.wrapError | 0xc000e3a340>: { msg: "error while waiting for pod azuredisk-8582/azuredisk-volume-tester-q9x7g to be Succeeded or Failed: pod \"azuredisk-volume-tester-q9x7g\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", err: <*errors.errorString | 0xc000736470>{ s: "pod \"azuredisk-volume-tester-q9x7g\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] QOSClass:BestEffort EphemeralContainerStatuses:[]}", }, } Jan 29 04:38:03.287: FAIL: error while waiting for pod azuredisk-8582/azuredisk-volume-tester-q9x7g to be Succeeded or Failed: pod "azuredisk-volume-tester-q9x7g" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] QOSClass:BestEffort EphemeralContainerStatuses:[]} Full Stack Trace sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*TestPod).WaitForSuccess(0x2253857?) /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(0xc000933d78, {0x270dda0, 0xc0000feea0}, {0x26f8fa0, 0xc000816d20}, 0xc000c818c0?) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/dynamically_provisioned_volume_snapshot_tester.go:142 +0x1358 ... skipping 35 lines ... Jan 29 04:40:09.620: INFO: Claim "azuredisk-8582" in namespace "pvc-6nhsw" doesn't exist in the system Jan 29 04:40:09.620: INFO: deleting StorageClass azuredisk-8582-disk.csi.azure.com-dynamic-sc-d2ht9 [1mSTEP:[0m dump namespace information after failure [38;5;243m01/29/23 04:40:09.65[0m [1mSTEP:[0m Destroying namespace "azuredisk-8582" for this suite. [38;5;243m01/29/23 04:40:09.651[0m [38;5;243m<< End Captured GinkgoWriter Output[0m [38;5;9mJan 29 04:38:03.287: error while waiting for pod azuredisk-8582/azuredisk-volume-tester-q9x7g to be Succeeded or Failed: pod "azuredisk-volume-tester-q9x7g" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:38:00 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2023-01-29 04:37:23 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.240.0.4 PodIP:10.240.0.24 PodIPs:[{IP:10.240.0.24}] StartTime:2023-01-29 04:37:23 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2023-01-29 04:37:56 +0000 UTC,FinishedAt:2023-01-29 04:37:59 +0000 UTC,ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:sha256:152749f71f8fd6004056d15c7fd5791563072703171eb8dbd3e66b2ee67f8287 ContainerID:containerd://deb8a7ae80d6ddd1cb9ad4476ca232f04dac489abed445fcf7ac7fbe11cc3138 Started:0xc0006d7fff}] 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(0xc0001402d0) /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:271 +0x179 ... skipping 25 lines ... Jan 29 04:40:12.265: INFO: PersistentVolumeClaim pvc-flrz7 found but phase is Pending instead of Bound. Jan 29 04:40:14.293: INFO: PersistentVolumeClaim pvc-flrz7 found and phase=Bound (4.081940113s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:40:14.293[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:40:14.319[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:40:14.346[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:40:14.346[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:40:14.377[0m Jan 29 04:40:14.377: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jpvkb" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 29 04:40:14.406: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 28.981178ms Jan 29 04:40:16.434: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057795235s Jan 29 04:40:18.435: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.05797355s Jan 29 04:40:20.435: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.058245053s Jan 29 04:40:22.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.05593172s Jan 29 04:40:24.432: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.054888568s ... skipping 11 lines ... Jan 29 04:40:48.432: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=true. Elapsed: 34.055712676s Jan 29 04:40:50.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=true. Elapsed: 36.055896816s Jan 29 04:40:52.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=false. Elapsed: 38.056447281s Jan 29 04:40:54.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=false. Elapsed: 40.056750498s Jan 29 04:40:56.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.056633726s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:40:56.433[0m Jan 29 04:40:56.433: INFO: Pod "azuredisk-volume-tester-jpvkb" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/29/23 04:40:56.433[0m 2023/01/29 04:40:56 Running in Prow, converting AZURE_CREDENTIALS to AZURE_CREDENTIAL_FILE 2023/01/29 04:40:56 Reading credentials file /etc/azure-cred/credentials [1mSTEP:[0m Prow test resource group: kubetest-uvfoless [38;5;243m01/29/23 04:40:56.434[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-1ecea1e4-9f8f-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:40:56.435[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-1ecea1e4-9f8f-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:40:57.033[0m ... skipping 27 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:41:32.376[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:41:32.403[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:41:32.429[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:41:32.43[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/29/23 04:41:32.43[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/29/23 04:41:32.43[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:41:32.459[0m Jan 29 04:41:32.460: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vbjsv" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 29 04:41:32.499: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 39.648592ms Jan 29 04:41:34.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.068016003s Jan 29 04:41:36.533: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.073246682s Jan 29 04:41:38.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.068331658s Jan 29 04:41:40.527: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.067146028s Jan 29 04:41:42.526: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.066579389s ... skipping 7 lines ... Jan 29 04:41:58.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 26.067988285s Jan 29 04:42:00.527: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Running", Reason="", readiness=true. Elapsed: 28.066741293s Jan 29 04:42:02.527: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Running", Reason="", readiness=true. Elapsed: 30.067070633s Jan 29 04:42:04.529: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Running", Reason="", readiness=false. Elapsed: 32.068950771s Jan 29 04:42:06.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 34.068394374s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:42:06.528[0m Jan 29 04:42:06.529: INFO: Pod "azuredisk-volume-tester-vbjsv" satisfied condition "Succeeded or Failed" Jan 29 04:42:06.529: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-vbjsv" Jan 29 04:42:06.583: INFO: Pod azuredisk-volume-tester-vbjsv has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vbjsv in namespace azuredisk-7726 [38;5;243m01/29/23 04:42:06.583[0m Jan 29 04:42:06.639: INFO: deleting PVC "azuredisk-7726"/"pvc-6t2zc" Jan 29 04:42:06.639: INFO: Deleting PersistentVolumeClaim "pvc-6t2zc" ... skipping 57 lines ... Jan 29 04:40:12.265: INFO: PersistentVolumeClaim pvc-flrz7 found but phase is Pending instead of Bound. Jan 29 04:40:14.293: INFO: PersistentVolumeClaim pvc-flrz7 found and phase=Bound (4.081940113s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:40:14.293[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:40:14.319[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:40:14.346[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:40:14.346[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:40:14.377[0m Jan 29 04:40:14.377: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jpvkb" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 29 04:40:14.406: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 28.981178ms Jan 29 04:40:16.434: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.057795235s Jan 29 04:40:18.435: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.05797355s Jan 29 04:40:20.435: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.058245053s Jan 29 04:40:22.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.05593172s Jan 29 04:40:24.432: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.054888568s ... skipping 11 lines ... Jan 29 04:40:48.432: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=true. Elapsed: 34.055712676s Jan 29 04:40:50.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=true. Elapsed: 36.055896816s Jan 29 04:40:52.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=false. Elapsed: 38.056447281s Jan 29 04:40:54.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Running", Reason="", readiness=false. Elapsed: 40.056750498s Jan 29 04:40:56.433: INFO: Pod "azuredisk-volume-tester-jpvkb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.056633726s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:40:56.433[0m Jan 29 04:40:56.433: INFO: Pod "azuredisk-volume-tester-jpvkb" satisfied condition "Succeeded or Failed" [1mSTEP:[0m Checking Prow test resource group [38;5;243m01/29/23 04:40:56.433[0m [1mSTEP:[0m Prow test resource group: kubetest-uvfoless [38;5;243m01/29/23 04:40:56.434[0m [1mSTEP:[0m Creating external resource group: azuredisk-csi-driver-test-1ecea1e4-9f8f-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:40:56.435[0m [1mSTEP:[0m creating volume snapshot class with external rg azuredisk-csi-driver-test-1ecea1e4-9f8f-11ed-9fb5-26fb55b0482f [38;5;243m01/29/23 04:40:57.033[0m [1mSTEP:[0m setting up the VolumeSnapshotClass [38;5;243m01/29/23 04:40:57.033[0m [1mSTEP:[0m creating a VolumeSnapshotClass [38;5;243m01/29/23 04:40:57.033[0m ... skipping 25 lines ... [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:41:32.376[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:41:32.403[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:41:32.429[0m [1mSTEP:[0m setting up the pod [38;5;243m01/29/23 04:41:32.43[0m [1mSTEP:[0m Set pod anti-affinity to make sure two pods are scheduled on different nodes [38;5;243m01/29/23 04:41:32.43[0m [1mSTEP:[0m deploying a pod with a volume restored from the snapshot [38;5;243m01/29/23 04:41:32.43[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:41:32.459[0m Jan 29 04:41:32.460: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-vbjsv" in namespace "azuredisk-7726" to be "Succeeded or Failed" Jan 29 04:41:32.499: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 39.648592ms Jan 29 04:41:34.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.068016003s Jan 29 04:41:36.533: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.073246682s Jan 29 04:41:38.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.068331658s Jan 29 04:41:40.527: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.067146028s Jan 29 04:41:42.526: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.066579389s ... skipping 7 lines ... Jan 29 04:41:58.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Pending", Reason="", readiness=false. Elapsed: 26.067988285s Jan 29 04:42:00.527: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Running", Reason="", readiness=true. Elapsed: 28.066741293s Jan 29 04:42:02.527: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Running", Reason="", readiness=true. Elapsed: 30.067070633s Jan 29 04:42:04.529: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Running", Reason="", readiness=false. Elapsed: 32.068950771s Jan 29 04:42:06.528: INFO: Pod "azuredisk-volume-tester-vbjsv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 34.068394374s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:42:06.528[0m Jan 29 04:42:06.529: INFO: Pod "azuredisk-volume-tester-vbjsv" satisfied condition "Succeeded or Failed" Jan 29 04:42:06.529: INFO: deleting Pod "azuredisk-7726"/"azuredisk-volume-tester-vbjsv" Jan 29 04:42:06.583: INFO: Pod azuredisk-volume-tester-vbjsv has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-vbjsv in namespace azuredisk-7726 [38;5;243m01/29/23 04:42:06.583[0m Jan 29 04:42:06.639: INFO: deleting PVC "azuredisk-7726"/"pvc-6t2zc" Jan 29 04:42:06.639: INFO: Deleting PersistentVolumeClaim "pvc-6t2zc" ... skipping 80 lines ... Jan 29 04:44:24.258: INFO: PersistentVolumeClaim pvc-6p8nv found but phase is Pending instead of Bound. Jan 29 04:44:26.286: INFO: PersistentVolumeClaim pvc-6p8nv found and phase=Bound (4.08895243s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:44:26.286[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:44:26.312[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:44:26.338[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:44:26.338[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:44:26.366[0m Jan 29 04:44:26.366: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-sdhvg" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 29 04:44:26.404: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 38.246989ms Jan 29 04:44:28.431: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065579328s Jan 29 04:44:30.431: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.065001262s Jan 29 04:44:32.432: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.06626301s Jan 29 04:44:34.430: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.064130754s Jan 29 04:44:36.432: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.066614472s ... skipping 17 lines ... Jan 29 04:45:12.432: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=true. Elapsed: 46.06633684s Jan 29 04:45:14.430: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=true. Elapsed: 48.064579409s Jan 29 04:45:16.433: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=false. Elapsed: 50.066997487s Jan 29 04:45:18.434: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=false. Elapsed: 52.068342796s Jan 29 04:45:20.431: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 54.06530343s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:45:20.431[0m Jan 29 04:45:20.431: INFO: Pod "azuredisk-volume-tester-sdhvg" satisfied condition "Succeeded or Failed" Jan 29 04:45:20.431: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-sdhvg" Jan 29 04:45:20.498: INFO: Pod azuredisk-volume-tester-sdhvg has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-sdhvg in namespace azuredisk-3086 [38;5;243m01/29/23 04:45:20.498[0m Jan 29 04:45:20.542: INFO: deleting PVC "azuredisk-3086"/"pvc-6p8nv" Jan 29 04:45:20.542: INFO: Deleting PersistentVolumeClaim "pvc-6p8nv" ... skipping 88 lines ... Jan 29 04:44:24.258: INFO: PersistentVolumeClaim pvc-6p8nv found but phase is Pending instead of Bound. Jan 29 04:44:26.286: INFO: PersistentVolumeClaim pvc-6p8nv found and phase=Bound (4.08895243s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:44:26.286[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:44:26.312[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:44:26.338[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:44:26.338[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:44:26.366[0m Jan 29 04:44:26.366: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-sdhvg" in namespace "azuredisk-3086" to be "Succeeded or Failed" Jan 29 04:44:26.404: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 38.246989ms Jan 29 04:44:28.431: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.065579328s Jan 29 04:44:30.431: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.065001262s Jan 29 04:44:32.432: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.06626301s Jan 29 04:44:34.430: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.064130754s Jan 29 04:44:36.432: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.066614472s ... skipping 17 lines ... Jan 29 04:45:12.432: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=true. Elapsed: 46.06633684s Jan 29 04:45:14.430: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=true. Elapsed: 48.064579409s Jan 29 04:45:16.433: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=false. Elapsed: 50.066997487s Jan 29 04:45:18.434: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Running", Reason="", readiness=false. Elapsed: 52.068342796s Jan 29 04:45:20.431: INFO: Pod "azuredisk-volume-tester-sdhvg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 54.06530343s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:45:20.431[0m Jan 29 04:45:20.431: INFO: Pod "azuredisk-volume-tester-sdhvg" satisfied condition "Succeeded or Failed" Jan 29 04:45:20.431: INFO: deleting Pod "azuredisk-3086"/"azuredisk-volume-tester-sdhvg" Jan 29 04:45:20.498: INFO: Pod azuredisk-volume-tester-sdhvg has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-sdhvg in namespace azuredisk-3086 [38;5;243m01/29/23 04:45:20.498[0m Jan 29 04:45:20.542: INFO: deleting PVC "azuredisk-3086"/"pvc-6p8nv" Jan 29 04:45:20.542: INFO: Deleting PersistentVolumeClaim "pvc-6p8nv" ... skipping 547 lines ... I0129 04:53:45.823422 15502 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0129 04:53:47.824707 15502 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/29/23 04:53:47.853[0m [1mSTEP:[0m check pod exec [38;5;243m01/29/23 04:53:47.882[0m Jan 29 04:53:47.883: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-1166 exec azuredisk-volume-tester-tvbt7-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:53:48.510: INFO: rc: 1 Jan 29 04:53:48.510: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-tvbt7-0": error running /usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-1166 exec azuredisk-volume-tester-tvbt7-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 29 04:53:50.511: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-1166 exec azuredisk-volume-tester-tvbt7-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:53:50.980: INFO: stderr: "" Jan 29 04:53:50.980: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/29/23 04:53:50.98[0m Jan 29 04:53:50.980: INFO: Deleting pod "azuredisk-volume-tester-tvbt7-0" in namespace "azuredisk-1166" ... skipping 51 lines ... I0129 04:53:45.823422 15502 testsuites.go:762] 0/1 replicas in the StatefulSet are ready I0129 04:53:47.824707 15502 testsuites.go:762] 1/1 replicas in the StatefulSet are ready [1mSTEP:[0m checking that the pod is running [38;5;243m01/29/23 04:53:47.853[0m [1mSTEP:[0m check pod exec [38;5;243m01/29/23 04:53:47.882[0m Jan 29 04:53:47.883: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-1166 exec azuredisk-volume-tester-tvbt7-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:53:48.510: INFO: rc: 1 Jan 29 04:53:48.510: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-tvbt7-0": error running /usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-1166 exec azuredisk-volume-tester-tvbt7-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 29 04:53:50.511: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uvfoless.centralus.cloudapp.azure.com --kubeconfig=/root/tmp1926250854/kubeconfig/kubeconfig.centralus.json --namespace=azuredisk-1166 exec azuredisk-volume-tester-tvbt7-0 -- cmd /c type C:\mnt\test-1\data.txt' Jan 29 04:53:50.980: INFO: stderr: "" Jan 29 04:53:50.980: INFO: stdout: "hello world\r\n" [1mSTEP:[0m deleting the pod for statefulset [38;5;243m01/29/23 04:53:50.98[0m Jan 29 04:53:50.980: INFO: Deleting pod "azuredisk-volume-tester-tvbt7-0" in namespace "azuredisk-1166" ... skipping 176 lines ... Jan 29 04:54:56.555: INFO: PersistentVolumeClaim pvc-phdzx found but phase is Pending instead of Bound. Jan 29 04:54:58.582: INFO: PersistentVolumeClaim pvc-phdzx found and phase=Bound (2.053760399s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:54:58.582[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:54:58.608[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:54:58.635[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:54:58.635[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/29/23 04:54:58.673[0m Jan 29 04:54:58.673: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-j4g8g" in namespace "azuredisk-5399" to be "Error status code" Jan 29 04:54:58.707: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 33.282549ms Jan 29 04:55:00.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.061642911s Jan 29 04:55:02.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.061301025s Jan 29 04:55:04.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.061487818s Jan 29 04:55:06.737: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.063182984s Jan 29 04:55:08.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.061497609s ... skipping 13 lines ... Jan 29 04:55:36.736: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 38.062899515s Jan 29 04:55:38.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 40.061356222s Jan 29 04:55:40.734: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=true. Elapsed: 42.060489265s Jan 29 04:55:42.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=true. Elapsed: 44.061405965s Jan 29 04:55:44.738: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=false. Elapsed: 46.064910628s Jan 29 04:55:46.736: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=false. Elapsed: 48.062601812s Jan 29 04:55:48.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Failed", Reason="", readiness=false. Elapsed: 50.061754343s [1mSTEP:[0m Saw pod failure [38;5;243m01/29/23 04:55:48.735[0m Jan 29 04:55:48.735: INFO: Pod "azuredisk-volume-tester-j4g8g" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/29/23 04:55:48.735[0m Jan 29 04:55:48.767: INFO: deleting Pod "azuredisk-5399"/"azuredisk-volume-tester-j4g8g" Jan 29 04:55:48.796: INFO: Pod azuredisk-volume-tester-j4g8g 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 56 lines ... Jan 29 04:54:56.555: INFO: PersistentVolumeClaim pvc-phdzx found but phase is Pending instead of Bound. Jan 29 04:54:58.582: INFO: PersistentVolumeClaim pvc-phdzx found and phase=Bound (2.053760399s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:54:58.582[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:54:58.608[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:54:58.635[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:54:58.635[0m [1mSTEP:[0m checking that the pod's command exits with an error [38;5;243m01/29/23 04:54:58.673[0m Jan 29 04:54:58.673: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-j4g8g" in namespace "azuredisk-5399" to be "Error status code" Jan 29 04:54:58.707: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 33.282549ms Jan 29 04:55:00.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.061642911s Jan 29 04:55:02.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.061301025s Jan 29 04:55:04.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.061487818s Jan 29 04:55:06.737: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.063182984s Jan 29 04:55:08.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.061497609s ... skipping 13 lines ... Jan 29 04:55:36.736: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 38.062899515s Jan 29 04:55:38.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Pending", Reason="", readiness=false. Elapsed: 40.061356222s Jan 29 04:55:40.734: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=true. Elapsed: 42.060489265s Jan 29 04:55:42.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=true. Elapsed: 44.061405965s Jan 29 04:55:44.738: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=false. Elapsed: 46.064910628s Jan 29 04:55:46.736: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Running", Reason="", readiness=false. Elapsed: 48.062601812s Jan 29 04:55:48.735: INFO: Pod "azuredisk-volume-tester-j4g8g": Phase="Failed", Reason="", readiness=false. Elapsed: 50.061754343s [1mSTEP:[0m Saw pod failure [38;5;243m01/29/23 04:55:48.735[0m Jan 29 04:55:48.735: INFO: Pod "azuredisk-volume-tester-j4g8g" satisfied condition "Error status code" [1mSTEP:[0m checking that pod logs contain expected message [38;5;243m01/29/23 04:55:48.735[0m Jan 29 04:55:48.767: INFO: deleting Pod "azuredisk-5399"/"azuredisk-volume-tester-j4g8g" Jan 29 04:55:48.796: INFO: Pod azuredisk-volume-tester-j4g8g has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied. At line:1 char:22 + ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 137 lines ... [1mSTEP:[0m Successfully provisioned a shared disk volume: "/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/single-shared-disk" [38;5;243m01/29/23 04:56:30.308[0m [1mSTEP:[0m Destroying namespace "azuredisk-8675" for this suite. [38;5;243m01/29/23 04:56:35.671[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/29/23 04:56:35.701[0m Jan 29 04:56:35.702: INFO: >>> kubeConfig: /root/tmp1926250854/kubeconfig/kubeconfig.centralus.json [1mSTEP:[0m Building a namespace api object, basename azuredisk [38;5;243m01/29/23 04:56:35.703[0m [1mSTEP:[0m Waiting for a default service account to be provisioned in namespace [38;5;243m01/29/23 04:56:35.785[0m [1mSTEP:[0m Waiting for kube-root-ca.crt to be provisioned in namespace [38;5;243m01/29/23 04:56:35.836[0m ... skipping 2 lines ... [38;5;243m------------------------------[0m [38;5;10m• [0.214 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/29/23 04:56:35.701[0m Jan 29 04:56:35.702: INFO: >>> kubeConfig: /root/tmp1926250854/kubeconfig/kubeconfig.centralus.json [1mSTEP:[0m Building a namespace api object, basename azuredisk [38;5;243m01/29/23 04:56:35.703[0m ... skipping 89 lines ... Jan 29 04:56:49.013: INFO: PersistentVolumeClaim pvc-rbzr2 found and phase=Bound (2.067226223s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:56:49.013[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:56:49.039[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:56:49.066[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/29/23 04:56:49.117[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:56:54.779[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:56:54.808[0m Jan 29 04:56:54.808: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p5sjn" in namespace "azuredisk-1533" to be "Succeeded or Failed" Jan 29 04:56:54.842: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 34.524846ms Jan 29 04:56:56.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06181531s Jan 29 04:56:58.871: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.062750174s Jan 29 04:57:00.872: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.063650346s Jan 29 04:57:02.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.062098515s Jan 29 04:57:04.872: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.063965312s ... skipping 19 lines ... Jan 29 04:57:44.872: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=true. Elapsed: 50.063676706s Jan 29 04:57:46.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=true. Elapsed: 52.061877162s Jan 29 04:57:48.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=false. Elapsed: 54.06229286s Jan 29 04:57:50.871: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=false. Elapsed: 56.063272778s Jan 29 04:57:52.881: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.072829452s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:57:52.881[0m Jan 29 04:57:52.881: INFO: Pod "azuredisk-volume-tester-p5sjn" satisfied condition "Succeeded or Failed" Jan 29 04:57:52.881: INFO: deleting Pod "azuredisk-1533"/"azuredisk-volume-tester-p5sjn" Jan 29 04:57:52.942: INFO: Pod azuredisk-volume-tester-p5sjn has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-p5sjn in namespace azuredisk-1533 [38;5;243m01/29/23 04:57:52.942[0m Jan 29 04:57:53.081: INFO: deleting PVC "azuredisk-1533"/"pvc-rbzr2" Jan 29 04:57:53.081: INFO: Deleting PersistentVolumeClaim "pvc-rbzr2" ... skipping 38 lines ... Jan 29 04:56:49.013: INFO: PersistentVolumeClaim pvc-rbzr2 found and phase=Bound (2.067226223s) [1mSTEP:[0m checking the PVC [38;5;243m01/29/23 04:56:49.013[0m [1mSTEP:[0m validating provisioned PV [38;5;243m01/29/23 04:56:49.039[0m [1mSTEP:[0m checking the PV [38;5;243m01/29/23 04:56:49.066[0m [1mSTEP:[0m attaching disk to node#0 [38;5;243m01/29/23 04:56:49.117[0m [1mSTEP:[0m deploying the pod [38;5;243m01/29/23 04:56:54.779[0m [1mSTEP:[0m checking that the pod's command exits with no error [38;5;243m01/29/23 04:56:54.808[0m Jan 29 04:56:54.808: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-p5sjn" in namespace "azuredisk-1533" to be "Succeeded or Failed" Jan 29 04:56:54.842: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 34.524846ms Jan 29 04:56:56.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.06181531s Jan 29 04:56:58.871: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.062750174s Jan 29 04:57:00.872: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.063650346s Jan 29 04:57:02.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.062098515s Jan 29 04:57:04.872: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Pending", Reason="", readiness=false. Elapsed: 10.063965312s ... skipping 19 lines ... Jan 29 04:57:44.872: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=true. Elapsed: 50.063676706s Jan 29 04:57:46.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=true. Elapsed: 52.061877162s Jan 29 04:57:48.870: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=false. Elapsed: 54.06229286s Jan 29 04:57:50.871: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Running", Reason="", readiness=false. Elapsed: 56.063272778s Jan 29 04:57:52.881: INFO: Pod "azuredisk-volume-tester-p5sjn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.072829452s [1mSTEP:[0m Saw pod success [38;5;243m01/29/23 04:57:52.881[0m Jan 29 04:57:52.881: INFO: Pod "azuredisk-volume-tester-p5sjn" satisfied condition "Succeeded or Failed" Jan 29 04:57:52.881: INFO: deleting Pod "azuredisk-1533"/"azuredisk-volume-tester-p5sjn" Jan 29 04:57:52.942: INFO: Pod azuredisk-volume-tester-p5sjn has the following logs: hello world [1mSTEP:[0m Deleting pod azuredisk-volume-tester-p5sjn in namespace azuredisk-1533 [38;5;243m01/29/23 04:57:52.942[0m Jan 29 04:57:53.081: INFO: deleting PVC "azuredisk-1533"/"pvc-rbzr2" Jan 29 04:57:53.081: INFO: Deleting PersistentVolumeClaim "pvc-rbzr2" ... skipping 108 lines ... Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0129 04:19:38.260848 1 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df e2e-test I0129 04:19:38.261649 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0129 04:19:38.298178 1 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 35 milliseconds I0129 04:19:38.298967 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 I0129 04:19:38.298979 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0129 04:19:38.299008 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0129 04:19:38.299039 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0129 04:19:38.300688 1 azure_auth.go:253] Using AzurePublicCloud environment I0129 04:19:38.300761 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0129 04:19:38.300799 1 azure.go:776] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 ... skipping 25 lines ... I0129 04:19:38.301515 1 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0129 04:19:38.301572 1 azure_vmasclient.go:70] Azure AvailabilitySetsClient (read ops) using rate limit config: QPS=100, bucket=1000 I0129 04:19:38.301580 1 azure_vmasclient.go:73] Azure AvailabilitySetsClient (write ops) using rate limit config: QPS=100, bucket=1000 I0129 04:19:38.301835 1 azure.go:1007] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0129 04:19:38.301886 1 azuredisk.go:192] disable UseInstanceMetadata for controller I0129 04:19:38.301898 1 azuredisk.go:204] cloud: AzurePublicCloud, location: centralus, rg: kubetest-uvfoless, VMType: standard, PrimaryScaleSetName: , PrimaryAvailabilitySetName: windowspool1-availabilitySet-11042790, DisableAvailabilitySetNodes: false I0129 04:19:38.306183 1 mount_linux.go:287] 'umount /tmp/kubelet-detect-safe-umount2438407047' failed with: exit status 32, output: umount: /tmp/kubelet-detect-safe-umount2438407047: must be superuser to unmount. I0129 04:19:38.306243 1 mount_linux.go:289] Detected umount with unsafe 'not mounted' behavior I0129 04:19:38.306355 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_VOLUME I0129 04:19:38.306366 1 driver.go:81] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0129 04:19:38.306373 1 driver.go:81] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0129 04:19:38.306380 1 driver.go:81] Enabling controller service capability: CLONE_VOLUME I0129 04:19:38.306385 1 driver.go:81] Enabling controller service capability: EXPAND_VOLUME ... skipping 131 lines ... I0129 04:21:50.490241 1 azure_controller_common.go:398] Trying to detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3 from node 1104k8s000, diskMap: map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/kubetest-uvfoless/providers/microsoft.compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3:pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3] E0129 04:21:50.490507 1 azure_controller_standard.go:189] detach azure disk on node(1104k8s000): disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/kubetest-uvfoless/providers/microsoft.compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3:pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3]) not found I0129 04:21:50.490693 1 azure_controller_standard.go:210] azureDisk - update(kubetest-uvfoless): vm(1104k8s000) - detach disk list(1104k8s000)%!(EXTRA map[string]string=map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/kubetest-uvfoless/providers/microsoft.compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3:pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3]) I0129 04:21:54.184689 1 utils.go:77] GRPC call: /csi.v1.Controller/DeleteVolume I0129 04:21:54.184715 1 utils.go:78] GRPC request: {"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3"} I0129 04:21:54.185315 1 controllerserver.go:317] deleting azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3) I0129 04:21:54.185346 1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3) returned with failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3) since it's in attaching or detaching state I0129 04:21:54.185455 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5e-05 request="azuredisk_csi_driver_controller_delete_volume" resource_group="kubetest-uvfoless" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3" result_code="failed_csi_driver_controller_delete_volume" E0129 04:21:54.185523 1 utils.go:82] GRPC error: failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3) since it's in attaching or detaching state I0129 04:21:55.759290 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.268355883 request="vm_update" resource_group="kubetest-uvfoless" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="detach_disk" error_code="" I0129 04:21:55.759321 1 azure_controller_standard.go:236] azureDisk - update(kubetest-uvfoless): vm(1104k8s000) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/kubetest-uvfoless/providers/microsoft.compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3:pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3]) returned with <nil> I0129 04:21:55.759342 1 azure_controller_standard.go:126] DeleteCacheForNode(1104k8s000) successfully I0129 04:21:55.759431 1 azure_controller_standard.go:272] updateCache(1104k8s000) successfully I0129 04:21:55.759444 1 azure_controller_common.go:422] azureDisk - detach disk(pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3) succeeded I0129 04:21:55.759507 1 controllerserver.go:480] detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3 from node 1104k8s000 successfully ... skipping 13 lines ... I0129 04:22:31.362105 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.174660487 request="azuredisk_csi_driver_controller_delete_volume" resource_group="kubetest-uvfoless" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-0d854b7a-8d34-4b91-bb8e-788252a23ce3" result_code="succeeded" I0129 04:22:31.362329 1 utils.go:84] GRPC response: {} I0129 04:22:34.201791 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0129 04:22:34.202089 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-c58884df-d617-42b2-91e6-060b334a3fe1","parameters":{"csi.storage.k8s.io/pv/name":"pvc-c58884df-d617-42b2-91e6-060b334a3fe1","csi.storage.k8s.io/pvc/name":"pvc-9f945","csi.storage.k8s.io/pvc/namespace":"azuredisk-2540","enableAsyncAttach":"false","networkAccessPolicy":"DenyAll","skuName":"Standard_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0129 04:22:34.203582 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0129 04:22:34.227383 1 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 23 milliseconds I0129 04:22:34.227860 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 I0129 04:22:34.228079 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0129 04:22:34.228440 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0129 04:22:34.228755 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0129 04:22:34.229860 1 azure_auth.go:253] Using AzurePublicCloud environment I0129 04:22:34.229937 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0129 04:22:34.229957 1 azure.go:776] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 ... skipping 116 lines ... I0129 04:24:19.112859 1 utils.go:78] GRPC request: {} I0129 04:24:19.112915 1 utils.go:84] GRPC response: {"ready":{"value":true}} I0129 04:24:19.428350 1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume I0129 04:24:19.428385 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-9a28b55e-7f3b-4da8-99ce-9d566b9476f2","parameters":{"csi.storage.k8s.io/pv/name":"pvc-9a28b55e-7f3b-4da8-99ce-9d566b9476f2","csi.storage.k8s.io/pvc/name":"pvc-z5jlf","csi.storage.k8s.io/pvc/namespace":"azuredisk-4728","enableAsyncAttach":"false","enableBursting":"true","perfProfile":"Basic","skuName":"Premium_LRS","userAgent":"azuredisk-e2e-test"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":7}}]} I0129 04:24:19.429455 1 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0129 04:24:19.462096 1 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 32 milliseconds I0129 04:24:19.462277 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 I0129 04:24:19.462301 1 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0129 04:24:19.462311 1 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json I0129 04:24:19.462357 1 azure_disk_utils.go:192] read cloud config from file: /etc/kubernetes/azure.json successfully I0129 04:24:19.462826 1 azure_auth.go:253] Using AzurePublicCloud environment I0129 04:24:19.462888 1 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0129 04:24:19.462935 1 azure.go:776] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 ... skipping 1706 lines ... I0129 04:57:10.394497 1 azure_controller_standard.go:236] azureDisk - update(kubetest-uvfoless): vm(1104k8s000) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/kubetest-uvfoless/providers/microsoft.compute/disks/reattach-disk-multiple-nodes:reattach-disk-multiple-nodes]) returned with <nil> I0129 04:57:10.394521 1 azure_controller_standard.go:126] DeleteCacheForNode(1104k8s000) successfully I0129 04:57:10.394530 1 azure_controller_standard.go:272] updateCache(1104k8s000) successfully I0129 04:57:10.394540 1 azure_controller_common.go:422] azureDisk - detach disk(reattach-disk-multiple-nodes, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) succeeded I0129 04:57:10.394559 1 controllerserver.go:425] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node 1104k8s001 again I0129 04:57:10.394606 1 azure_controller_common.go:194] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node 1104k8s000, could not be attached to node(1104k8s001) E0129 04:57:10.394638 1 controllerserver.go:429] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance 1104k8s001 failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/virtualMachines/1104k8s000), could not be attached to node(1104k8s001) I0129 04:57:10.394778 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=15.490754929 request="azuredisk_csi_driver_controller_publish_volume" resource_group="kubetest-uvfoless" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="1104k8s001" result_code="failed_csi_driver_controller_publish_volume" E0129 04:57:10.394803 1 utils.go:82] GRPC error: rpc error: code = Internal desc = Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance 1104k8s001 failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/virtualMachines/1104k8s000), could not be attached to node(1104k8s001) I0129 04:57:10.409595 1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume I0129 04:57:10.409618 1 utils.go:78] GRPC request: {"node_id":"1104k8s001","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/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"} I0129 04:57:10.435709 1 util.go:124] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 977 I0129 04:57:10.436086 1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.0258472 request="disks_get" resource_group="kubetest-uvfoless" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code="" I0129 04:57:10.436146 1 controllerserver.go:383] GetDiskLun returned: cannot find Lun for disk reattach-disk-multiple-nodes. Initiating attaching volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node 1104k8s001 (vmState Succeeded). I0129 04:57:10.436193 1 controllerserver.go:408] Trying to attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to node 1104k8s001 ... skipping 124 lines ... Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0129 04:19:58.364670 6536 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df e2e-test I0129 04:19:58.383230 6536 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0129 04:19:58.417635 6536 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 32 milliseconds I0129 04:19:58.419981 6536 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 I0129 04:19:58.419981 6536 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0129 04:19:58.419981 6536 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0129 04:19:58.425178 6536 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0129 04:19:58.426343 6536 azure_auth.go:253] Using AzurePublicCloud environment I0129 04:19:58.426927 6536 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0129 04:19:58.428205 6536 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 929 lines ... Topology Key: topology.disk.csi.azure.com/zone Streaming logs below: I0129 04:19:59.779738 6624 azuredisk.go:175] driver userAgent: disk.csi.azure.com/v1.27.0-db7daf80cf6d95173fec925514d6a1d9169180df e2e-test I0129 04:19:59.800723 6624 azure_disk_utils.go:162] reading cloud config from secret kube-system/azure-cloud-provider I0129 04:19:59.850747 6624 round_trippers.go:553] GET https://10.0.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 48 milliseconds I0129 04:19:59.854508 6624 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 I0129 04:19:59.854508 6624 azure_disk_utils.go:174] could not read cloud config from secret kube-system/azure-cloud-provider I0129 04:19:59.854508 6624 azure_disk_utils.go:184] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json I0129 04:19:59.861407 6624 azure_disk_utils.go:192] read cloud config from file: C:\k\azure.json successfully I0129 04:19:59.863214 6624 azure_auth.go:253] Using AzurePublicCloud environment I0129 04:19:59.863296 6624 azure_auth.go:138] azure: using client_id+client_secret to retrieve access token I0129 04:19:59.864479 6624 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 ... skipping 466 lines ... I0129 04:35:14.774089 6624 nodeserver.go:206] NodeUnstageVolume: unmount \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\97991b4ecbdd7e49a3520ab2424ec95d44dec533d2844c1415964107c583f6dc\globalmount successfully I0129 04:35:14.774089 6624 utils.go:84] GRPC response: {} I0129 04:35:14.814603 6624 nodeserver.go:206] NodeUnstageVolume: unmount \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\10b9a42aec95f65aff7207655d1fbdb266547a2286fc6264b171a455c936983f\globalmount successfully I0129 04:35:14.814603 6624 utils.go:84] GRPC response: {} I0129 04:35:15.106911 6624 nodeserver.go:206] NodeUnstageVolume: unmount \var\lib\kubelet\plugins\kubernetes.io\csi\disk.csi.azure.com\109214c7f4fab1ac6b409181534092203aec75eb27b1b868721bbe2ddea0f5cc\globalmount successfully I0129 04:35:15.107440 6624 utils.go:84] GRPC response: {} E0129 04:35:15.317996 6624 utils.go:82] GRPC error: GetVolumeIDFromMount(c:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b842f2b960\volumes\kubernetes.io~csi\pvc-ced8df00-41bd-41d3-9792-1da1c233f4f2\mount) failed with error: rpc error: code = Unknown desc = error getting the volume for the mount c:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b842f2b960\volumes\kubernetes.io~csi\pvc-ced8df00-41bd-41d3-9792-1da1c233f4f2\mount, internal error error getting volume from mount. cmd: (Get-Item -Path Get-Item : Cannot find path 'C:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b842f2b960\volumes\kubernetes.io~csi\pvc -ced8df00-41bd-41d3-9792-1da1c233f4f2\mount' because it does not exist. At line:1 char:2 + (Get-Item -Path c:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b84 ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + CategoryInfo : ObjectNotFound: (C:\var\lib\kube...1c233f4f2\mount:String) [Get-Item], ItemNotFoundExcep tion ... skipping 37 lines ... + ... d : PathNotFound,Microsoft.PowerShell.Commands.GetItemCommand).Target + ~ Unexpected token ')' in expression or statement. + CategoryInfo : ParserError: (:) [], ParentContainsErrorRecordException + FullyQualifiedErrorId : MissingEndParenthesisInExpression , error: exit status 1, response: <nil> I0129 04:35:15.319803 6624 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities I0129 04:35:15.319803 6624 utils.go:78] GRPC request: {} I0129 04:35:15.319803 6624 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]} I0129 04:35:15.320746 6624 utils.go:77] GRPC call: /csi.v1.Node/NodeGetVolumeStats I0129 04:35:15.320746 6624 utils.go:78] GRPC request: {"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/kubetest-uvfoless/providers/Microsoft.Compute/disks/pvc-9b8bc50e-2229-40ab-a491-828364add04b","volume_path":"c:\\var\\lib\\kubelet\\pods\\5836ebb9-480c-4134-966b-a7b842f2b960\\volumes\\kubernetes.io~csi\\pvc-9b8bc50e-2229-40ab-a491-828364add04b\\mount"} E0129 04:35:15.865670 6624 utils.go:82] GRPC error: GetVolumeIDFromMount(c:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b842f2b960\volumes\kubernetes.io~csi\pvc-9b8bc50e-2229-40ab-a491-828364add04b\mount) failed with error: rpc error: code = Unknown desc = error getting the volume for the mount c:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b842f2b960\volumes\kubernetes.io~csi\pvc-9b8bc50e-2229-40ab-a491-828364add04b\mount, internal error error getting volume from mount. cmd: (Get-Item -Path Get-Item : Cannot find path 'C:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b842f2b960\volumes\kubernetes.io~csi\pvc -9b8bc50e-2229-40ab-a491-828364add04b\mount' because it does not exist. At line:1 char:2 + (Get-Item -Path c:\var\lib\kubelet\pods\5836ebb9-480c-4134-966b-a7b84 ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + CategoryInfo : ObjectNotFound: (C:\var\lib\kube...364add04b\mount:String) [Get-Item], ItemNotFoundExcep tion ... skipping 37 lines ... + ... d : PathNotFound,Microsoft.PowerShell.Commands.GetItemCommand).Target + ~ Unexpected token ')' in expression or statement. + CategoryInfo : ParserError: (:) [], ParentContainsErrorRecordException + FullyQualifiedErrorId : MissingEndParenthesisInExpression , error: exit status 1, response: <nil> I0129 04:35:20.668496 6624 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0129 04:35:20.668540 6624 utils.go:78] GRPC request: {} I0129 04:35:20.668617 6624 utils.go:84] GRPC response: {"ready":{"value":true}} I0129 04:35:50.665507 6624 utils.go:77] GRPC call: /csi.v1.Identity/Probe I0129 04:35:50.665507 6624 utils.go:78] GRPC request: {} I0129 04:35:50.665507 6624 utils.go:84] GRPC response: {"ready":{"value":true}} ... skipping 804 lines ... cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="kubetest-uvfoless",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="kubetest-uvfoless",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="kubetest-uvfoless",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="kubetest-uvfoless",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="kubetest-uvfoless",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 521.8455760270001 cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="kubetest-uvfoless",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_delete_volume",resource_group="kubetest-uvfoless",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1 cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="kubetest-uvfoless",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1 # HELP disabled_metric_total [ALPHA] The count of disabled metrics. # TYPE disabled_metric_total counter disabled_metric_total 0 ... skipping 68 lines ... # HELP go_gc_heap_objects_objects Number of objects, live or unswept, occupying heap memory. # TYPE go_gc_heap_objects_objects gauge go_gc_heap_objects_objects 29277 # 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 27342 # 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 270 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 and read to it, take a volume snapshot, and create another pod from the snapshot [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 22 of 66 Specs in 2774.604 seconds[0m [38;5;9m[1mFAIL![0m -- [38;5;10m[1m21 Passed[0m | [38;5;9m[1m1 Failed[0m | [38;5;11m[1m0 Pending[0m | [38;5;14m[1m44 Skipped[0m [38;5;228mYou're using deprecated Ginkgo functionality:[0m [38;5;228m=============================================[0m [38;5;11mSupport for custom reporters has been removed in V2. Please read the documentation linked to below for Ginkgo's new behavior and for a migration path:[0m [1mLearn more at:[0m [38;5;14m[4mhttps://onsi.github.io/ginkgo/MIGRATING_TO_V2#removed-custom-reporters[0m [38;5;243mTo silence deprecations that can be silenced set the following environment variable:[0m [38;5;243mACK_GINKGO_DEPRECATIONS=2.4.0[0m --- FAIL: TestE2E (2774.61s) FAIL FAIL sigs.k8s.io/azuredisk-csi-driver/test/e2e 2774.672s FAIL make: *** [Makefile:261: e2e-test] Error 1 2023/01/29 05:00:09 process.go:155: Step 'make e2e-test' finished in 47m58.05485446s 2023/01/29 05:00:09 aksengine_helpers.go:425: downloading /root/tmp1926250854/log-dump.sh from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh 2023/01/29 05:00:09 util.go:70: curl https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh 2023/01/29 05:00:09 process.go:153: Running: chmod +x /root/tmp1926250854/log-dump.sh 2023/01/29 05:00:09 process.go:155: Step 'chmod +x /root/tmp1926250854/log-dump.sh' finished in 3.160986ms 2023/01/29 05:00:09 aksengine_helpers.go:425: downloading /root/tmp1926250854/log-dump-daemonset.yaml from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump-daemonset.yaml ... skipping 109 lines ... Flags -d Detailed option, when used with list, dumps the json of the object Write-Progress : Win32 internal error "Access is denied" 0x5 occurred while reading the console output buffer. Contact Microsoft Customer Support Services. At C:\windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Archive\Microsoft.PowerShell.Archive.psm1:1132 char:9 + Write-Progress -Activity $cmdletName -Status $status -Percent ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 53 lines ... Flags -d Detailed option, when used with list, dumps the json of the object Write-Progress : Win32 internal error "Access is denied" 0x5 occurred while reading the console output buffer. Contact Microsoft Customer Support Services. At C:\windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Archive\Microsoft.PowerShell.Archive.psm1:1132 char:9 + Write-Progress -Activity $cmdletName -Status $status -Percent ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ... skipping 8 lines ... Warning: Permanently added '1104k8s001' (ECDSA) to the list of known hosts. Collecting logs for vm 1104k8s002 Testing connection to host 1104k8s002. Warning: Permanently added 'kubetest-uvfoless.centralus.cloudapp.azure.com,13.89.105.68' (ECDSA) to the list of known hosts. Authorized uses only. All activity may be monitored and reported. channel 0: open failed: connect failed: Name or service not known stdio forwarding failed ssh_exchange_identification: Connection closed by remote host 2023/01/29 05:01:23 process.go:155: Step 'bash -c /root/tmp1926250854/win-ci-logs-collector.sh kubetest-uvfoless.centralus.cloudapp.azure.com /root/tmp1926250854 /etc/ssh-key-secret/ssh-private' finished in 50.636399964s 2023/01/29 05:01:23 aksengine.go:1141: Deleting resource group: kubetest-uvfoless. 2023/01/29 05:06:39 process.go:96: Saved XML output to /logs/artifacts/junit_runner.xml. 2023/01/29 05:06:39 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" 2023/01/29 05:06:41 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 1.562583324s 2023/01/29 05:06:41 main.go:328: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] + EXIT_VALUE=1 + set +o xtrace Cleaning up after docker in docker. ================================================================================ Cleaning up after docker f4df3974e16d ... skipping 4 lines ...