This job view page is being replaced by Spyglass soon. Check out the new job view.
PRandyzhangx: [WIP]doc: cut v1.25.0 release
ResultFAILURE
Tests 1 failed / 21 succeeded
Started2022-11-17 10:14
Elapsed1h47m
Revision1084cff826c5fdef349c9af66c94d153624a9c34
Refs 1604

Test Failures

AzureDisk CSI Driver End-to-End Tests Dynamic Provisioning [single-az] should create a pod, write to its pv, take a volume snapshot, overwrite data in original pv, create another pod from the snapshot, and read unaltered original data from original pv[disk.csi.azure.com] 10m28s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=AzureDisk\sCSI\sDriver\sEnd\-to\-End\sTests\sDynamic\sProvisioning\s\[single\-az\]\sshould\screate\sa\spod\,\swrite\sto\sits\spv\,\stake\sa\svolume\ssnapshot\,\soverwrite\sdata\sin\soriginal\spv\,\screate\sanother\spod\sfrom\sthe\ssnapshot\,\sand\sread\sunaltered\soriginal\sdata\sfrom\soriginal\spv\[disk\.csi\.azure\.com\]$'
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:672
Unexpected error:
    <*errors.errorString | 0xc0003f2410>: {
        s: "pod \"azuredisk-volume-tester-gjhff\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.39.67 PodIPs:[{IP:192.168.39.67}] StartTime:2022-11-17 11:19:44 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2022-11-17 11:26:07 +0000 UTC,FinishedAt:2022-11-17 11:26:16 +0000 UTC,ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:cbb8b0a709b4e0868cd2e30b1485358197b1021bb0dd4261e36b3af3ca48fd0b ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6 Started:0xc000952cad}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
    }
    pod "azuredisk-volume-tester-gjhff" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.39.67 PodIPs:[{IP:192.168.39.67}] StartTime:2022-11-17 11:19:44 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2022-11-17 11:26:07 +0000 UTC,FinishedAt:2022-11-17 11:26:16 +0000 UTC,ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:cbb8b0a709b4e0868cd2e30b1485358197b1021bb0dd4261e36b3af3ca48fd0b ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6 Started:0xc000952cad}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
occurred
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:825
				
				Click to see stdout/stderrfrom junit_01.xml

Find azuredisk-volume-tester-gjhff mentions in log files | View test history on testgrid

Show 21 Passed Tests
Show 40 Skipped Tests

Error lines from build-log.txt

... skipping 759 lines ...
certificate.cert-manager.io "selfsigned-cert" deleted
# Create secret for AzureClusterIdentity
./hack/create-identity-secret.sh
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
make[2]: Nothing to be done for 'kubectl'.
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
Error from server (NotFound): secrets "cluster-identity-secret" not found
secret/cluster-identity-secret created
secret/cluster-identity-secret labeled
# Create customized cloud provider configs
./hack/create-custom-cloud-provider-config.sh
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure'
make[2]: Nothing to be done for 'kubectl'.
... skipping 186 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11156  100 11156    0     0   157k      0 --:--:-- --:--:-- --:--:--  157k
Downloading https://get.helm.sh/helm-v3.10.2-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull capzci.azurecr.io/azuredisk-csi:v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9 || make container-all push-manifest
Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9 not found: manifest unknown: manifest tagged by "v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9" 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.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=6b7ec56f9e2955e776323b54159120e3bde3deb9 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2022-11-17T10:33:48Z -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 1793 lines ...
                    type: string
                type: object
                oneOf:
                - required: ["persistentVolumeClaimName"]
                - required: ["volumeSnapshotContentName"]
              volumeSnapshotClassName:
                description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.'
                type: string
            required:
            - source
            type: object
          status:
            description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.
... skipping 2 lines ...
                description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.'
                type: string
              creationTime:
                description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown.
                format: date-time
                type: string
              error:
                description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared.
                properties:
                  message:
                    description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.'
                    type: string
                  time:
                    description: time is the timestamp when the error was encountered.
                    format: date-time
                    type: string
                type: object
              readyToUse:
                description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown.
                type: boolean
              restoreSize:
                type: string
                description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown.
                pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$
                x-kubernetes-int-or-string: true
            type: object
        required:
        - spec
        type: object
... skipping 60 lines ...
                    type: string
                  volumeSnapshotContentName:
                    description: volumeSnapshotContentName specifies the name of a pre-existing VolumeSnapshotContent object representing an existing volume snapshot. This field should be set if the snapshot already exists and only needs a representation in Kubernetes. This field is immutable.
                    type: string
                type: object
              volumeSnapshotClassName:
                description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.'
                type: string
            required:
            - source
            type: object
          status:
            description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.
... skipping 2 lines ...
                description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.'
                type: string
              creationTime:
                description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown.
                format: date-time
                type: string
              error:
                description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared.
                properties:
                  message:
                    description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.'
                    type: string
                  time:
                    description: time is the timestamp when the error was encountered.
                    format: date-time
                    type: string
                type: object
              readyToUse:
                description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown.
                type: boolean
              restoreSize:
                type: string
                description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown.
                pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$
                x-kubernetes-int-or-string: true
            type: object
        required:
        - spec
        type: object
... skipping 254 lines ...
            description: status represents the current information of a snapshot.
            properties:
              creationTime:
                description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it indicates the creation time is unknown. The format of this field is a Unix nanoseconds time encoded as an int64. On Unix, the command `date +%s%N` returns the current time in nanoseconds since 1970-01-01 00:00:00 UTC.
                format: int64
                type: integer
              error:
                description: error is the last observed error during snapshot creation, if any. Upon success after retry, this error field will be cleared.
                properties:
                  message:
                    description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.'
                    type: string
                  time:
                    description: time is the timestamp when the error was encountered.
                    format: date-time
                    type: string
                type: object
              readyToUse:
                description: readyToUse indicates if a snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown.
                type: boolean
              restoreSize:
                description: restoreSize represents the complete size of the snapshot in bytes. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown.
                format: int64
                minimum: 0
                type: integer
              snapshotHandle:
                description: snapshotHandle is the CSI "snapshot_id" of a snapshot on the underlying storage system. If not specified, it indicates that dynamic snapshot creation has either failed or it is still in progress.
                type: string
            type: object
        required:
        - spec
        type: object
    served: true
... skipping 108 lines ...
            description: status represents the current information of a snapshot.
            properties:
              creationTime:
                description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it indicates the creation time is unknown. The format of this field is a Unix nanoseconds time encoded as an int64. On Unix, the command `date +%s%N` returns the current time in nanoseconds since 1970-01-01 00:00:00 UTC.
                format: int64
                type: integer
              error:
                description: error is the last observed error during snapshot creation, if any. Upon success after retry, this error field will be cleared.
                properties:
                  message:
                    description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.'
                    type: string
                  time:
                    description: time is the timestamp when the error was encountered.
                    format: date-time
                    type: string
                type: object
              readyToUse:
                description: readyToUse indicates if a snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown.
                type: boolean
              restoreSize:
                description: restoreSize represents the complete size of the snapshot in bytes. In dynamic snapshot creation case, this field will be filled in by the CSI snapshotter sidecar with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown.
                format: int64
                minimum: 0
                type: integer
              snapshotHandle:
                description: snapshotHandle is the CSI "snapshot_id" of a snapshot on the underlying storage system. If not specified, it indicates that dynamic snapshot creation has either failed or it is still in progress.
                type: string
            type: object
        required:
        - spec
        type: object
    served: true
... skipping 613 lines ...
          image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.5.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 215 lines ...
Nov 17 10:45:47.786: INFO: PersistentVolumeClaim pvc-phnw2 found and phase=Bound (4.334269379s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 10:45:48.119: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-58njs" in namespace "azuredisk-8081" to be "Succeeded or Failed"
Nov 17 10:45:48.229: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Pending", Reason="", readiness=false. Elapsed: 109.654659ms
Nov 17 10:45:50.339: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219467119s
Nov 17 10:45:52.449: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Pending", Reason="", readiness=false. Elapsed: 4.329187825s
Nov 17 10:45:54.559: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Pending", Reason="", readiness=false. Elapsed: 6.439969964s
Nov 17 10:45:56.670: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Pending", Reason="", readiness=false. Elapsed: 8.550550609s
Nov 17 10:45:58.784: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Pending", Reason="", readiness=false. Elapsed: 10.664275773s
... skipping 271 lines ...
Nov 17 10:55:34.698: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Running", Reason="", readiness=true. Elapsed: 9m46.578258437s
Nov 17 10:55:36.814: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Running", Reason="", readiness=false. Elapsed: 9m48.694657017s
Nov 17 10:55:38.935: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Running", Reason="", readiness=false. Elapsed: 9m50.815220257s
Nov 17 10:55:41.053: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Running", Reason="", readiness=false. Elapsed: 9m52.933227912s
Nov 17 10:55:43.170: INFO: Pod "azuredisk-volume-tester-58njs": Phase="Succeeded", Reason="", readiness=false. Elapsed: 9m55.050872407s
STEP: Saw pod success
Nov 17 10:55:43.170: INFO: Pod "azuredisk-volume-tester-58njs" satisfied condition "Succeeded or Failed"
Nov 17 10:55:43.170: INFO: deleting Pod "azuredisk-8081"/"azuredisk-volume-tester-58njs"
Nov 17 10:55:43.319: INFO: Pod azuredisk-volume-tester-58njs has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-58njs in namespace azuredisk-8081
Nov 17 10:55:43.446: INFO: deleting PVC "azuredisk-8081"/"pvc-phnw2"
Nov 17 10:55:43.446: INFO: Deleting PersistentVolumeClaim "pvc-phnw2"
... skipping 45 lines ...
Nov 17 10:56:28.942: INFO: PersistentVolumeClaim pvc-lcl4z found but phase is Pending instead of Bound.
Nov 17 10:56:31.051: INFO: PersistentVolumeClaim pvc-lcl4z found and phase=Bound (4.328850811s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Nov 17 10:56:31.389: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-hs6rk" in namespace "azuredisk-2540" to be "Succeeded or Failed"
Nov 17 10:56:31.498: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Pending", Reason="", readiness=false. Elapsed: 108.800819ms
Nov 17 10:56:33.607: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217947758s
Nov 17 10:56:35.718: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.328688541s
Nov 17 10:56:37.828: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Pending", Reason="", readiness=false. Elapsed: 6.438599872s
Nov 17 10:56:39.938: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Pending", Reason="", readiness=false. Elapsed: 8.548773685s
Nov 17 10:56:42.048: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Pending", Reason="", readiness=false. Elapsed: 10.658527369s
... skipping 23 lines ...
Nov 17 10:57:32.753: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Running", Reason="", readiness=true. Elapsed: 1m1.363581881s
Nov 17 10:57:34.870: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Running", Reason="", readiness=false. Elapsed: 1m3.480021401s
Nov 17 10:57:36.985: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Running", Reason="", readiness=false. Elapsed: 1m5.595977648s
Nov 17 10:57:39.103: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Running", Reason="", readiness=false. Elapsed: 1m7.71312814s
Nov 17 10:57:41.219: INFO: Pod "azuredisk-volume-tester-hs6rk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m9.82978338s
STEP: Saw pod success
Nov 17 10:57:41.219: INFO: Pod "azuredisk-volume-tester-hs6rk" satisfied condition "Succeeded or Failed"
Nov 17 10:57:41.219: INFO: deleting Pod "azuredisk-2540"/"azuredisk-volume-tester-hs6rk"
Nov 17 10:57:41.355: INFO: Pod azuredisk-volume-tester-hs6rk has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-hs6rk in namespace azuredisk-2540
Nov 17 10:57:41.494: INFO: deleting PVC "azuredisk-2540"/"pvc-lcl4z"
Nov 17 10:57:41.494: INFO: Deleting PersistentVolumeClaim "pvc-lcl4z"
... skipping 46 lines ...
Nov 17 10:58:29.215: INFO: PersistentVolumeClaim pvc-q5kbb found and phase=Bound (4.34335936s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 10:58:29.550: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-4g6ct" in namespace "azuredisk-4728" to be "Succeeded or Failed"
Nov 17 10:58:29.659: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Pending", Reason="", readiness=false. Elapsed: 108.75512ms
Nov 17 10:58:31.769: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219033478s
Nov 17 10:58:33.880: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Pending", Reason="", readiness=false. Elapsed: 4.330117128s
Nov 17 10:58:35.991: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Pending", Reason="", readiness=false. Elapsed: 6.441051307s
Nov 17 10:58:38.102: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Pending", Reason="", readiness=false. Elapsed: 8.551931901s
Nov 17 10:58:40.215: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Pending", Reason="", readiness=false. Elapsed: 10.664818945s
... skipping 20 lines ...
Nov 17 10:59:24.578: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Running", Reason="", readiness=true. Elapsed: 55.02791426s
Nov 17 10:59:26.696: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Running", Reason="", readiness=true. Elapsed: 57.145740626s
Nov 17 10:59:28.812: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Running", Reason="", readiness=false. Elapsed: 59.261997752s
Nov 17 10:59:30.929: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Running", Reason="", readiness=false. Elapsed: 1m1.378464151s
Nov 17 10:59:33.046: INFO: Pod "azuredisk-volume-tester-4g6ct": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m3.495342664s
STEP: Saw pod success
Nov 17 10:59:33.046: INFO: Pod "azuredisk-volume-tester-4g6ct" satisfied condition "Succeeded or Failed"
Nov 17 10:59:33.046: INFO: deleting Pod "azuredisk-4728"/"azuredisk-volume-tester-4g6ct"
Nov 17 10:59:33.181: INFO: Pod azuredisk-volume-tester-4g6ct has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-4g6ct in namespace azuredisk-4728
Nov 17 10:59:33.312: INFO: deleting PVC "azuredisk-4728"/"pvc-q5kbb"
Nov 17 10:59:33.312: INFO: Deleting PersistentVolumeClaim "pvc-q5kbb"
... skipping 102 lines ...
Nov 17 11:00:24.718: INFO: PersistentVolumeClaim pvc-h9wvv found and phase=Bound (4.334637253s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with an error
Nov 17 11:00:25.057: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-6hdkv" in namespace "azuredisk-5356" to be "Error status code"
Nov 17 11:00:25.167: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Pending", Reason="", readiness=false. Elapsed: 110.144939ms
Nov 17 11:00:27.280: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.223155487s
Nov 17 11:00:29.393: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.336305613s
Nov 17 11:00:31.506: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.449518268s
Nov 17 11:00:33.619: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.56208298s
Nov 17 11:00:35.730: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.673829437s
... skipping 33 lines ...
Nov 17 11:01:47.562: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Running", Reason="", readiness=true. Elapsed: 1m22.50566446s
Nov 17 11:01:49.679: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Running", Reason="", readiness=true. Elapsed: 1m24.622509884s
Nov 17 11:01:51.796: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Running", Reason="", readiness=true. Elapsed: 1m26.739593024s
Nov 17 11:01:53.914: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Running", Reason="", readiness=false. Elapsed: 1m28.857239438s
Nov 17 11:01:56.030: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Running", Reason="", readiness=false. Elapsed: 1m30.973668637s
Nov 17 11:01:58.148: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Running", Reason="", readiness=false. Elapsed: 1m33.091359182s
Nov 17 11:02:00.265: INFO: Pod "azuredisk-volume-tester-6hdkv": Phase="Failed", Reason="", readiness=false. Elapsed: 1m35.208741084s
STEP: Saw pod failure
Nov 17 11:02:00.265: INFO: Pod "azuredisk-volume-tester-6hdkv" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Nov 17 11:02:00.413: INFO: deleting Pod "azuredisk-5356"/"azuredisk-volume-tester-6hdkv"
Nov 17 11:02:00.531: INFO: Pod azuredisk-volume-tester-6hdkv 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 219 lines ...
Nov 17 11:09:12.975: 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(2022, time.November, 17, 11, 8, 26, 0, time.Local), LastTransitionTime:time.Date(2022, time.November, 17, 11, 8, 26, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.November, 17, 11, 8, 26, 0, time.Local), LastTransitionTime:time.Date(2022, time.November, 17, 11, 8, 26, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-6bzrj-67f49595f7\" is progressing."}}, CollisionCount:(*int32)(nil)}
Nov 17 11:09:14.975: 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(2022, time.November, 17, 11, 8, 26, 0, time.Local), LastTransitionTime:time.Date(2022, time.November, 17, 11, 8, 26, 0, time.Local), Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:time.Date(2022, time.November, 17, 11, 8, 26, 0, time.Local), LastTransitionTime:time.Date(2022, time.November, 17, 11, 8, 26, 0, time.Local), Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-6bzrj-67f49595f7\" is progressing."}}, CollisionCount:(*int32)(nil)}
STEP: checking that the pod is running
STEP: check pod exec
Nov 17 11:09:17.439: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1353 exec azuredisk-volume-tester-6bzrj-67f49595f7-sggzr -- cmd /c type C:\mnt\test-1\data.txt'
Nov 17 11:09:18.840: INFO: rc: 1
Nov 17 11:09:18.840: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-6bzrj-67f49595f7-sggzr": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1353 exec azuredisk-volume-tester-6bzrj-67f49595f7-sggzr -- 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.
Nov 17 11:09:20.841: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-1353 exec azuredisk-volume-tester-6bzrj-67f49595f7-sggzr -- cmd /c type C:\mnt\test-1\data.txt'
Nov 17 11:09:22.037: INFO: stderr: ""
Nov 17 11:09:22.037: INFO: stdout: "hello world\r\n"
STEP: deleting the pod for deployment
Nov 17 11:09:22.037: INFO: Deleting pod "azuredisk-volume-tester-6bzrj-67f49595f7-sggzr" in namespace "azuredisk-1353"
... skipping 236 lines ...
Nov 17 11:10:58.877: INFO: PersistentVolumeClaim pvc-c6bx6 found and phase=Bound (4.328997963s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 11:10:59.209: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-v5cmw" in namespace "azuredisk-59" to be "Succeeded or Failed"
Nov 17 11:10:59.325: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Pending", Reason="", readiness=false. Elapsed: 115.68269ms
Nov 17 11:11:01.441: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.232177288s
Nov 17 11:11:03.559: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.349745161s
Nov 17 11:11:05.676: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.466989622s
Nov 17 11:11:07.793: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.583765015s
Nov 17 11:11:09.909: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.699719532s
... skipping 30 lines ...
Nov 17 11:12:15.507: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Running", Reason="", readiness=true. Elapsed: 1m16.29727171s
Nov 17 11:12:17.623: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Running", Reason="", readiness=false. Elapsed: 1m18.414033564s
Nov 17 11:12:19.739: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Running", Reason="", readiness=false. Elapsed: 1m20.529790591s
Nov 17 11:12:21.855: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Running", Reason="", readiness=false. Elapsed: 1m22.645585437s
Nov 17 11:12:23.975: INFO: Pod "azuredisk-volume-tester-v5cmw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m24.765783243s
STEP: Saw pod success
Nov 17 11:12:23.975: INFO: Pod "azuredisk-volume-tester-v5cmw" satisfied condition "Succeeded or Failed"
Nov 17 11:12:23.975: INFO: deleting Pod "azuredisk-59"/"azuredisk-volume-tester-v5cmw"
Nov 17 11:12:24.117: INFO: Pod azuredisk-volume-tester-v5cmw has the following logs: hello world
hello world
hello world

STEP: Deleting pod azuredisk-volume-tester-v5cmw in namespace azuredisk-59
... skipping 96 lines ...
Nov 17 11:13:35.223: INFO: PersistentVolumeClaim pvc-97pjx found but phase is Pending instead of Bound.
Nov 17 11:13:37.332: INFO: PersistentVolumeClaim pvc-97pjx found and phase=Bound (6.439739034s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 11:13:37.669: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-59l8f" in namespace "azuredisk-1598" to be "Succeeded or Failed"
Nov 17 11:13:37.778: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Pending", Reason="", readiness=false. Elapsed: 108.756237ms
Nov 17 11:13:39.887: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218198419s
Nov 17 11:13:42.000: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.330827766s
Nov 17 11:13:44.111: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.441951323s
Nov 17 11:13:46.222: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.55306676s
Nov 17 11:13:48.333: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Pending", Reason="", readiness=false. Elapsed: 10.663901312s
... skipping 20 lines ...
Nov 17 11:14:32.695: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Running", Reason="", readiness=true. Elapsed: 55.026387639s
Nov 17 11:14:34.813: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Running", Reason="", readiness=false. Elapsed: 57.143801345s
Nov 17 11:14:36.930: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Running", Reason="", readiness=false. Elapsed: 59.261431713s
Nov 17 11:14:39.047: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Running", Reason="", readiness=false. Elapsed: 1m1.378102042s
Nov 17 11:14:41.165: INFO: Pod "azuredisk-volume-tester-59l8f": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m3.496218933s
STEP: Saw pod success
Nov 17 11:14:41.165: INFO: Pod "azuredisk-volume-tester-59l8f" satisfied condition "Succeeded or Failed"
STEP: Checking Prow test resource group
STEP: Prow test resource group: capz-qc0900
STEP: Creating external resource group: azuredisk-csi-driver-test-0816fdc9-6669-11ed-a509-aaa8d76c0811
STEP: creating volume snapshot class with external rg azuredisk-csi-driver-test-0816fdc9-6669-11ed-a509-aaa8d76c0811
STEP: setting up the VolumeSnapshotClass
STEP: creating a VolumeSnapshotClass
... skipping 11 lines ...
Nov 17 11:15:02.900: INFO: PersistentVolumeClaim pvc-vcdhp found and phase=Bound (4.330029541s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: deploying a pod with a volume restored from the snapshot
STEP: checking that the pod's command exits with no error
Nov 17 11:15:03.234: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-2bbfj" in namespace "azuredisk-1598" to be "Succeeded or Failed"
Nov 17 11:15:03.345: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Pending", Reason="", readiness=false. Elapsed: 110.786688ms
Nov 17 11:15:05.455: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.221278815s
Nov 17 11:15:07.566: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.332289062s
Nov 17 11:15:09.676: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.441837284s
Nov 17 11:15:11.786: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.55210116s
Nov 17 11:15:13.898: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.663707201s
... skipping 17 lines ...
Nov 17 11:15:51.928: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Running", Reason="", readiness=true. Elapsed: 48.694234629s
Nov 17 11:15:54.045: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Running", Reason="", readiness=true. Elapsed: 50.811164973s
Nov 17 11:15:56.162: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Running", Reason="", readiness=false. Elapsed: 52.928256525s
Nov 17 11:15:58.279: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Running", Reason="", readiness=false. Elapsed: 55.045034378s
Nov 17 11:16:00.396: INFO: Pod "azuredisk-volume-tester-2bbfj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 57.161752045s
STEP: Saw pod success
Nov 17 11:16:00.396: INFO: Pod "azuredisk-volume-tester-2bbfj" satisfied condition "Succeeded or Failed"
Nov 17 11:16:00.396: INFO: deleting Pod "azuredisk-1598"/"azuredisk-volume-tester-2bbfj"
Nov 17 11:16:00.543: INFO: Pod azuredisk-volume-tester-2bbfj has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-2bbfj in namespace azuredisk-1598
Nov 17 11:16:00.759: INFO: deleting PVC "azuredisk-1598"/"pvc-vcdhp"
Nov 17 11:16:00.759: INFO: Deleting PersistentVolumeClaim "pvc-vcdhp"
... skipping 61 lines ...
Nov 17 11:18:13.939: INFO: PersistentVolumeClaim pvc-blftj found but phase is Pending instead of Bound.
Nov 17 11:18:16.051: INFO: PersistentVolumeClaim pvc-blftj found and phase=Bound (4.330581768s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 11:18:16.385: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-kwl4t" in namespace "azuredisk-3410" to be "Succeeded or Failed"
Nov 17 11:18:16.495: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Pending", Reason="", readiness=false. Elapsed: 109.67527ms
Nov 17 11:18:18.605: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220455472s
Nov 17 11:18:20.715: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Pending", Reason="", readiness=false. Elapsed: 4.33054426s
Nov 17 11:18:22.825: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Pending", Reason="", readiness=false. Elapsed: 6.440260322s
Nov 17 11:18:24.936: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Pending", Reason="", readiness=false. Elapsed: 8.551467266s
Nov 17 11:18:27.046: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Pending", Reason="", readiness=false. Elapsed: 10.661327051s
... skipping 18 lines ...
Nov 17 11:19:07.166: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Running", Reason="", readiness=true. Elapsed: 50.781370359s
Nov 17 11:19:09.283: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Running", Reason="", readiness=true. Elapsed: 52.897678595s
Nov 17 11:19:11.400: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Running", Reason="", readiness=true. Elapsed: 55.014878778s
Nov 17 11:19:13.515: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Running", Reason="", readiness=false. Elapsed: 57.130338019s
Nov 17 11:19:15.631: INFO: Pod "azuredisk-volume-tester-kwl4t": Phase="Succeeded", Reason="", readiness=false. Elapsed: 59.246191423s
STEP: Saw pod success
Nov 17 11:19:15.631: INFO: Pod "azuredisk-volume-tester-kwl4t" satisfied condition "Succeeded or Failed"
STEP: Checking Prow test resource group
STEP: Prow test resource group: capz-qc0900
STEP: Creating external resource group: azuredisk-csi-driver-test-abaf1cbf-6669-11ed-a509-aaa8d76c0811
STEP: creating volume snapshot class with external rg azuredisk-csi-driver-test-abaf1cbf-6669-11ed-a509-aaa8d76c0811
STEP: setting up the VolumeSnapshotClass
STEP: creating a VolumeSnapshotClass
... skipping 14 lines ...
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: setting up the pod
STEP: Set pod anti-affinity to make sure two pods are scheduled on different nodes
STEP: deploying a pod with a volume restored from the snapshot
STEP: checking that the pod's command exits with no error
Nov 17 11:19:44.865: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-gjhff" in namespace "azuredisk-3410" to be "Succeeded or Failed"
Nov 17 11:19:44.974: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Pending", Reason="", readiness=false. Elapsed: 108.638129ms
Nov 17 11:19:47.083: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217809298s
Nov 17 11:19:49.194: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Pending", Reason="", readiness=false. Elapsed: 4.328138235s
Nov 17 11:19:51.305: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Pending", Reason="", readiness=false. Elapsed: 6.439300922s
Nov 17 11:19:53.415: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Pending", Reason="", readiness=false. Elapsed: 8.549575739s
Nov 17 11:19:55.526: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Pending", Reason="", readiness=false. Elapsed: 10.660166366s
... skipping 176 lines ...
Nov 17 11:26:10.081: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Running", Reason="", readiness=true. Elapsed: 6m25.215569261s
Nov 17 11:26:12.198: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Running", Reason="", readiness=true. Elapsed: 6m27.332731221s
Nov 17 11:26:14.315: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Running", Reason="", readiness=true. Elapsed: 6m29.449345788s
Nov 17 11:26:16.432: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Running", Reason="", readiness=true. Elapsed: 6m31.566851358s
Nov 17 11:26:18.550: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Running", Reason="", readiness=false. Elapsed: 6m33.684214657s
Nov 17 11:26:20.666: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Running", Reason="", readiness=false. Elapsed: 6m35.800507749s
Nov 17 11:26:22.783: INFO: Pod "azuredisk-volume-tester-gjhff": Phase="Failed", Reason="", readiness=false. Elapsed: 6m37.917782411s
Nov 17 11:26:22.784: INFO: deleting Pod "azuredisk-3410"/"azuredisk-volume-tester-gjhff"
Nov 17 11:26:22.912: INFO: Pod azuredisk-volume-tester-gjhff has the following logs: 
STEP: Deleting pod azuredisk-volume-tester-gjhff in namespace azuredisk-3410
Nov 17 11:26:23.040: INFO: deleting PVC "azuredisk-3410"/"pvc-t7x78"
Nov 17 11:26:23.040: INFO: Deleting PersistentVolumeClaim "pvc-t7x78"
STEP: waiting for claim's PV "pvc-e6e10cc5-9630-4314-bdda-63174a7361c3" to be deleted
... skipping 156 lines ...
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:40
  [single-az]
  /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:43
    should create a pod, write to its pv, take a volume snapshot, overwrite data in original pv, create another pod from the snapshot, and read unaltered original data from original pv[disk.csi.azure.com] [It]
    /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning_test.go:672

    Unexpected error:
        <*errors.errorString | 0xc0003f2410>: {
            s: "pod \"azuredisk-volume-tester-gjhff\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.39.67 PodIPs:[{IP:192.168.39.67}] StartTime:2022-11-17 11:19:44 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2022-11-17 11:26:07 +0000 UTC,FinishedAt:2022-11-17 11:26:16 +0000 UTC,ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:cbb8b0a709b4e0868cd2e30b1485358197b1021bb0dd4261e36b3af3ca48fd0b ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6 Started:0xc000952cad}] QOSClass:BestEffort EphemeralContainerStatuses:[]}",
        }
        pod "azuredisk-volume-tester-gjhff" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:26:18 +0000 UTC Reason:PodFailed Message:} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2022-11-17 11:19:44 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.1.0.5 PodIP:192.168.39.67 PodIPs:[{IP:192.168.39.67}] StartTime:2022-11-17 11:19:44 +0000 UTC InitContainerStatuses:[] ContainerStatuses:[{Name:volume-tester State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:1,Signal:0,Reason:Error,Message:,StartedAt:2022-11-17 11:26:07 +0000 UTC,FinishedAt:2022-11-17 11:26:16 +0000 UTC,ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:mcr.microsoft.com/windows/servercore:ltsc2019 ImageID:mcr.microsoft.com/windows/servercore@sha256:cbb8b0a709b4e0868cd2e30b1485358197b1021bb0dd4261e36b3af3ca48fd0b ContainerID:containerd://321754ffb593643d333de1ff8fd2d12f6b633550a29dbc8567e21acb5d90acd6 Started:0xc000952cad}] QOSClass:BestEffort EphemeralContainerStatuses:[]}
    occurred

    /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:825
------------------------------
Dynamic Provisioning [single-az] 
  should create a pod with multiple volumes [kubernetes.io/azure-disk] [disk.csi.azure.com] [Windows]
... skipping 42 lines ...
Nov 17 11:28:51.571: INFO: PersistentVolumeClaim pvc-rsccs found but phase is Pending instead of Bound.
Nov 17 11:28:53.681: INFO: PersistentVolumeClaim pvc-rsccs found and phase=Bound (4.329671172s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 11:28:54.013: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-ppsfj" in namespace "azuredisk-8582" to be "Succeeded or Failed"
Nov 17 11:28:54.124: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Pending", Reason="", readiness=false. Elapsed: 110.915422ms
Nov 17 11:28:56.237: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.22338645s
Nov 17 11:28:58.352: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.338535674s
Nov 17 11:29:00.464: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.450859573s
Nov 17 11:29:02.576: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.562847528s
Nov 17 11:29:04.690: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Pending", Reason="", readiness=false. Elapsed: 10.67656063s
... skipping 22 lines ...
Nov 17 11:29:53.271: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Running", Reason="", readiness=true. Elapsed: 59.257929753s
Nov 17 11:29:55.383: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Running", Reason="", readiness=true. Elapsed: 1m1.369245097s
Nov 17 11:29:57.494: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Running", Reason="", readiness=false. Elapsed: 1m3.480362934s
Nov 17 11:29:59.606: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Running", Reason="", readiness=false. Elapsed: 1m5.592617221s
Nov 17 11:30:01.719: INFO: Pod "azuredisk-volume-tester-ppsfj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m7.70553704s
STEP: Saw pod success
Nov 17 11:30:01.719: INFO: Pod "azuredisk-volume-tester-ppsfj" satisfied condition "Succeeded or Failed"
Nov 17 11:30:01.719: INFO: deleting Pod "azuredisk-8582"/"azuredisk-volume-tester-ppsfj"
Nov 17 11:30:01.839: INFO: Pod azuredisk-volume-tester-ppsfj has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-ppsfj in namespace azuredisk-8582
Nov 17 11:30:01.962: INFO: deleting PVC "azuredisk-8582"/"pvc-rsccs"
Nov 17 11:30:01.962: INFO: Deleting PersistentVolumeClaim "pvc-rsccs"
... skipping 327 lines ...
I1117 11:39:30.606192   37287 testsuites.go:764] 0/1 replicas in the StatefulSet are ready
I1117 11:39:32.606086   37287 testsuites.go:764] 1/1 replicas in the StatefulSet are ready
STEP: checking that the pod is running
STEP: check pod exec
Nov 17 11:39:32.837: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4801 exec azuredisk-volume-tester-vw7r6-0 -- cmd /c type C:\mnt\test-1\data.txt'
Nov 17 11:39:34.065: INFO: rc: 1
Nov 17 11:39:34.065: INFO: Error waiting for output "hello world\r\n" in pod "azuredisk-volume-tester-vw7r6-0": error running /usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4801 exec azuredisk-volume-tester-vw7r6-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.
Nov 17 11:39:36.066: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig --namespace=azuredisk-4801 exec azuredisk-volume-tester-vw7r6-0 -- cmd /c type C:\mnt\test-1\data.txt'
Nov 17 11:39:37.241: INFO: stderr: ""
Nov 17 11:39:37.241: INFO: stdout: "hello world\r\n"
STEP: deleting the pod for statefulset
Nov 17 11:39:37.241: INFO: Deleting pod "azuredisk-volume-tester-vw7r6-0" in namespace "azuredisk-4801"
... skipping 159 lines ...
Nov 17 11:41:04.748: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-v4plg] to have phase Bound
Nov 17 11:41:04.858: INFO: PersistentVolumeClaim pvc-v4plg found and phase=Bound (110.511151ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pod's command exits with an error
Nov 17 11:41:05.192: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-xh9nt" in namespace "azuredisk-6829" to be "Error status code"
Nov 17 11:41:05.301: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 108.649972ms
Nov 17 11:41:07.411: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218993601s
Nov 17 11:41:09.532: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.339731469s
Nov 17 11:41:11.642: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 6.450099351s
Nov 17 11:41:13.753: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 8.560920263s
Nov 17 11:41:15.865: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 10.673053952s
... skipping 13 lines ...
Nov 17 11:41:45.422: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Pending", Reason="", readiness=false. Elapsed: 40.230284714s
Nov 17 11:41:47.540: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Running", Reason="", readiness=true. Elapsed: 42.347577473s
Nov 17 11:41:49.656: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Running", Reason="", readiness=true. Elapsed: 44.464408175s
Nov 17 11:41:51.774: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Running", Reason="", readiness=false. Elapsed: 46.582384941s
Nov 17 11:41:53.890: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Running", Reason="", readiness=false. Elapsed: 48.698122832s
Nov 17 11:41:56.012: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Running", Reason="", readiness=false. Elapsed: 50.82028305s
Nov 17 11:41:58.129: INFO: Pod "azuredisk-volume-tester-xh9nt": Phase="Failed", Reason="", readiness=false. Elapsed: 52.937117429s
STEP: Saw pod failure
Nov 17 11:41:58.129: INFO: Pod "azuredisk-volume-tester-xh9nt" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Nov 17 11:41:58.264: INFO: deleting Pod "azuredisk-6829"/"azuredisk-volume-tester-xh9nt"
Nov 17 11:41:58.376: INFO: Pod azuredisk-volume-tester-xh9nt 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 101 lines ...
  [single-az]
  /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:69
    should succeed when creating a shared disk [disk.csi.azure.com][windows]
    /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:143
------------------------------
Pre-Provisioned [single-az] 
  should fail when maxShares is invalid [disk.csi.azure.com][windows]
  /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:164
STEP: Creating a kubernetes client
Nov 17 11:42:36.482: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: Building a namespace api object, basename azuredisk
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
... skipping 68 lines ...
Nov 17 11:42:50.117: INFO: PersistentVolumeClaim pvc-m2bp5 found and phase=Bound (108.765199ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: attaching disk to node#0
STEP: deploying the pod
STEP: checking that the pod's command exits with no error
Nov 17 11:43:01.880: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-9zgpb" in namespace "azuredisk-1661" to be "Succeeded or Failed"
Nov 17 11:43:01.990: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Pending", Reason="", readiness=false. Elapsed: 110.180446ms
Nov 17 11:43:04.101: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.221134539s
Nov 17 11:43:06.212: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.331974942s
Nov 17 11:43:08.322: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.441963824s
Nov 17 11:43:10.432: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.552071029s
Nov 17 11:43:12.543: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.66338358s
... skipping 30 lines ...
Nov 17 11:44:18.004: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Running", Reason="", readiness=true. Elapsed: 1m16.124273896s
Nov 17 11:44:20.133: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Running", Reason="", readiness=true. Elapsed: 1m18.252478697s
Nov 17 11:44:22.249: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Running", Reason="", readiness=true. Elapsed: 1m20.369307412s
Nov 17 11:44:24.365: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Running", Reason="", readiness=false. Elapsed: 1m22.484971569s
Nov 17 11:44:26.481: INFO: Pod "azuredisk-volume-tester-9zgpb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m24.600865826s
STEP: Saw pod success
Nov 17 11:44:26.481: INFO: Pod "azuredisk-volume-tester-9zgpb" satisfied condition "Succeeded or Failed"
Nov 17 11:44:26.481: INFO: deleting Pod "azuredisk-1661"/"azuredisk-volume-tester-9zgpb"
Nov 17 11:44:26.619: INFO: Pod azuredisk-volume-tester-9zgpb has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-9zgpb in namespace azuredisk-1661
Nov 17 11:44:26.994: INFO: deleting PVC "azuredisk-1661"/"pvc-m2bp5"
Nov 17 11:44:26.994: INFO: Deleting PersistentVolumeClaim "pvc-m2bp5"
... skipping 114 lines ...
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I1117 10:45:10.620704       1 azuredisk.go:172] driver userAgent: disk.csi.azure.com/v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9 e2e-test
I1117 10:45:10.622495       1 azure_disk_utils.go:161] reading cloud config from secret kube-system/azure-cloud-provider
I1117 10:45:10.636844       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 14 milliseconds
I1117 10:45:10.637135       1 azure_disk_utils.go:168] 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
I1117 10:45:10.637153       1 azure_disk_utils.go:173] could not read cloud config from secret kube-system/azure-cloud-provider
I1117 10:45:10.637162       1 azure_disk_utils.go:183] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I1117 10:45:10.637199       1 azure_disk_utils.go:191] read cloud config from file: /etc/kubernetes/azure.json successfully
I1117 10:45:10.637745       1 azure_auth.go:245] Using AzurePublicCloud environment
I1117 10:45:10.637794       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I1117 10:45:10.637872       1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02
... skipping 238 lines ...
I1117 10:56:19.783541       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.236490779 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-1d0156f0-6c41-49cb-ae5b-985da3ee6543" result_code="succeeded"
I1117 10:56:19.783564       1 utils.go:84] GRPC response: {}
I1117 10:56:26.688527       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I1117 10:56:26.688563       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-477195bd-5798-45e1-ae3a-7a3d0b76778a","parameters":{"csi.storage.k8s.io/pv/name":"pvc-477195bd-5798-45e1-ae3a-7a3d0b76778a","csi.storage.k8s.io/pvc/name":"pvc-lcl4z","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}}]}
I1117 10:56:26.689612       1 azure_disk_utils.go:161] reading cloud config from secret kube-system/azure-cloud-provider
I1117 10:56:26.700140       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 10 milliseconds
I1117 10:56:26.700376       1 azure_disk_utils.go:168] 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
I1117 10:56:26.700395       1 azure_disk_utils.go:173] could not read cloud config from secret kube-system/azure-cloud-provider
I1117 10:56:26.700517       1 azure_disk_utils.go:183] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I1117 10:56:26.700721       1 azure_disk_utils.go:191] read cloud config from file: /etc/kubernetes/azure.json successfully
I1117 10:56:26.701138       1 azure_auth.go:245] Using AzurePublicCloud environment
I1117 10:56:26.701390       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I1117 10:56:26.701482       1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02
... skipping 103 lines ...
I1117 10:58:17.874343       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=5.276817557 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-477195bd-5798-45e1-ae3a-7a3d0b76778a" result_code="succeeded"
I1117 10:58:17.874357       1 utils.go:84] GRPC response: {}
I1117 10:58:24.837419       1 utils.go:77] GRPC call: /csi.v1.Controller/CreateVolume
I1117 10:58:24.837442       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-75f04406-f419-43fd-b1e2-ecdfef4f9b0d","parameters":{"csi.storage.k8s.io/pv/name":"pvc-75f04406-f419-43fd-b1e2-ecdfef4f9b0d","csi.storage.k8s.io/pvc/name":"pvc-q5kbb","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}}]}
I1117 10:58:24.838416       1 azure_disk_utils.go:161] reading cloud config from secret kube-system/azure-cloud-provider
I1117 10:58:24.846894       1 round_trippers.go:553] GET https://10.96.0.1:443/api/v1/namespaces/kube-system/secrets/azure-cloud-provider 404 Not Found in 7 milliseconds
I1117 10:58:24.847221       1 azure_disk_utils.go:168] 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
I1117 10:58:24.847365       1 azure_disk_utils.go:173] could not read cloud config from secret kube-system/azure-cloud-provider
I1117 10:58:24.847517       1 azure_disk_utils.go:183] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I1117 10:58:24.847677       1 azure_disk_utils.go:191] read cloud config from file: /etc/kubernetes/azure.json successfully
I1117 10:58:24.848125       1 azure_auth.go:245] Using AzurePublicCloud environment
I1117 10:58:24.848447       1 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I1117 10:58:24.848641       1 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02
... skipping 479 lines ...
I1117 11:06:53.428398       1 azure_controller_common.go:351] Trying to detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804 from node capz-qc09-p42ll, diskMap: map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804:pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804]
E1117 11:06:53.431315       1 azure_controller_standard.go:168] detach azure disk on node(capz-qc09-p42ll): disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804:pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804]) not found
I1117 11:06:53.431344       1 azure_controller_standard.go:189] azureDisk - update(capz-qc0900): vm(capz-qc09-p42ll) - detach disk list(capz-qc09-p42ll)%!(EXTRA map[string]string=map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804:pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804])
I1117 11:06:53.533735       1 utils.go:77] GRPC call: /csi.v1.Controller/DeleteVolume
I1117 11:06:53.533758       1 utils.go:78] GRPC request: {"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804"}
I1117 11:06:53.533848       1 controllerserver.go:317] deleting azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804)
I1117 11:06:53.533870       1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804) returned with failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804) since it's in attaching or detaching state
I1117 11:06:53.533920       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=3.8702e-05 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804" result_code="failed_csi_driver_controller_delete_volume"
E1117 11:06:53.533931       1 utils.go:82] GRPC error: failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804) since it's in attaching or detaching state
I1117 11:06:53.962472       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.531078086 request="vm_update" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="detach_disk" error_code=""
I1117 11:06:53.962503       1 azure_controller_standard.go:206] azureDisk - update(capz-qc0900): vm(capz-qc09-p42ll) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804:pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804]) returned with <nil>
I1117 11:06:53.962532       1 azure_controller_common.go:375] azureDisk - detach disk(pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804) succeeded
I1117 11:06:53.962546       1 controllerserver.go:480] detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804 from node capz-qc09-p42ll successfully
I1117 11:06:53.962576       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.755084046 request="azuredisk_csi_driver_controller_unpublish_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-72d9dcf6-ad83-4c2c-911c-fc816b424804" node="capz-qc09-p42ll" result_code="succeeded"
I1117 11:06:53.962596       1 utils.go:84] GRPC response: {}
... skipping 1786 lines ...
I1117 11:38:39.502163       1 azure_controller_common.go:351] Trying to detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55 from node capz-qc09-p42ll, diskMap: map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55:pvc-a8990161-ca73-4568-b00e-11fa69781f55]
E1117 11:38:39.504831       1 azure_controller_standard.go:168] detach azure disk on node(capz-qc09-p42ll): disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55:pvc-a8990161-ca73-4568-b00e-11fa69781f55]) not found
I1117 11:38:39.504858       1 azure_controller_standard.go:189] azureDisk - update(capz-qc0900): vm(capz-qc09-p42ll) - detach disk list(capz-qc09-p42ll)%!(EXTRA map[string]string=map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55:pvc-a8990161-ca73-4568-b00e-11fa69781f55])
I1117 11:38:39.957602       1 utils.go:77] GRPC call: /csi.v1.Controller/DeleteVolume
I1117 11:38:39.957631       1 utils.go:78] GRPC request: {"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55"}
I1117 11:38:39.958016       1 controllerserver.go:317] deleting azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55)
I1117 11:38:39.958126       1 controllerserver.go:319] delete azure disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55) returned with failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55) since it's in attaching or detaching state
I1117 11:38:39.958230       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.000389524 request="azuredisk_csi_driver_controller_delete_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55" result_code="failed_csi_driver_controller_delete_volume"
E1117 11:38:39.958280       1 utils.go:82] GRPC error: failed to delete disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55) since it's in attaching or detaching state
I1117 11:38:40.084685       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.57978716 request="vm_update" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="detach_disk" error_code=""
I1117 11:38:40.084717       1 azure_controller_standard.go:206] azureDisk - update(capz-qc0900): vm(capz-qc09-p42ll) - detach disk list(map[/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourcegroups/capz-qc0900/providers/microsoft.compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55:pvc-a8990161-ca73-4568-b00e-11fa69781f55]) returned with <nil>
I1117 11:38:40.084744       1 azure_controller_common.go:375] azureDisk - detach disk(pvc-a8990161-ca73-4568-b00e-11fa69781f55, /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55) succeeded
I1117 11:38:40.084758       1 controllerserver.go:480] detach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55 from node capz-qc09-p42ll successfully
I1117 11:38:40.084792       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.791204517 request="azuredisk_csi_driver_controller_unpublish_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/pvc-a8990161-ca73-4568-b00e-11fa69781f55" node="capz-qc09-p42ll" result_code="succeeded"
I1117 11:38:40.084809       1 utils.go:84] GRPC response: {}
... skipping 280 lines ...
I1117 11:43:17.819022       1 azure_vmss_cache.go:421] Node capz-qc09-p42ll has joined the cluster since the last VM cache refresh in NonVmssUniformNodesEntry, refreshing the cache
I1117 11:43:17.819037       1 azure_vmss_cache.go:351] refresh the cache of NonVmssUniformNodesCache
I1117 11:43:17.870502       1 util.go:123] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 10739
I1117 11:43:17.871439       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.052343288 request="vm_list" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I1117 11:43:17.871466       1 azure_backoff.go:101] VirtualMachinesClient.List(capz-qc0900) success
I1117 11:43:17.871547       1 azure_controller_common.go:184] found dangling volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes attached to node capz-qc09-44zcq, could not be attached to node(capz-qc09-p42ll)
E1117 11:43:17.871598       1 controllerserver.go:429] Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-qc09-p42ll failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/virtualMachines/capz-qc09-44zcq), could not be attached to node(capz-qc09-p42ll)
I1117 11:43:17.871673       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=15.898506163 request="azuredisk_csi_driver_controller_publish_volume" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="disk.csi.azure.com" volumeid="/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes" node="capz-qc09-p42ll" result_code="failed_csi_driver_controller_publish_volume"
E1117 11:43:17.871772       1 utils.go:82] GRPC error: rpc error: code = Internal desc = Attach volume /subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes to instance capz-qc09-p42ll failed with disk(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes) already attached to node(/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/virtualMachines/capz-qc09-44zcq), could not be attached to node(capz-qc09-p42ll)
I1117 11:43:17.887059       1 utils.go:77] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I1117 11:43:17.887311       1 utils.go:78] GRPC request: {"node_id":"capz-qc09-p42ll","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":7}},"volume_context":{"cachingMode":"None","requestedsizegib":"10","skuName":"Premium_LRS"},"volume_id":"/subscriptions/0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e/resourceGroups/capz-qc0900/providers/Microsoft.Compute/disks/reattach-disk-multiple-nodes"}
I1117 11:43:17.917975       1 util.go:123] Send.sendRequest got response with ContentLength -1, StatusCode 200 and responseBody length 972
I1117 11:43:17.918254       1 azure_metrics.go:115] "Observed Request Latency" latency_seconds=0.03071187 request="disks_get" resource_group="capz-qc0900" subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e" source="" error_code=""
I1117 11:43:17.918346       1 azure_vmss_cache.go:421] Node capz-qc09-p42ll has joined the cluster since the last VM cache refresh in NonVmssUniformNodesEntry, refreshing the cache
I1117 11:43:17.918358       1 azure_vmss_cache.go:351] refresh the cache of NonVmssUniformNodesCache
... skipping 207 lines ...
Go Version: go1.19.3
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I1117 10:45:40.986789    5352 azuredisk.go:172] driver userAgent: disk.csi.azure.com/v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9 e2e-test
W1117 10:45:40.986789    5352 azure_disk_utils.go:229] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified.
I1117 10:45:40.986789    5352 azure_disk_utils.go:173] could not read cloud config from secret kube-system/azure-cloud-provider
I1117 10:45:40.986789    5352 azure_disk_utils.go:183] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I1117 10:45:40.986789    5352 azure_disk_utils.go:191] read cloud config from file: C:\k\azure.json successfully
I1117 10:45:40.992751    5352 azure_auth.go:245] Using AzurePublicCloud environment
I1117 10:45:40.992751    5352 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I1117 10:45:41.000796    5352 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02
... skipping 20 lines ...
I1117 10:45:41.062384    5352 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9"}
I1117 10:45:41.885642    5352 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I1117 10:45:41.885709    5352 utils.go:78] GRPC request: {}
I1117 10:45:41.902777    5352 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I1117 10:45:41.902777    5352 utils.go:78] GRPC request: {}
I1117 10:45:41.902956    5352 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9"}
I1117 10:45:41.920123    5352 azure_instance_metadata.go:139] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I1117 10:45:41.928962    5352 nodeserver.go:370] NodeGetInfo: nodeName(capz-qc09-p42ll), VM Size(Standard_D4s_v3)
I1117 10:45:41.928962    5352 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I1117 10:45:41.928962    5352 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-qc09-p42ll"}
I1117 10:46:02.107801    5352 utils.go:77] GRPC call: /csi.v1.Node/NodeGetCapabilities
I1117 10:46:02.107927    5352 utils.go:78] GRPC request: {}
I1117 10:46:02.108015    5352 utils.go:84] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":3}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
... skipping 1311 lines ...
Go Version: go1.19.3
Platform: windows/amd64
Topology Key: topology.disk.csi.azure.com/zone

Streaming logs below:
I1117 10:45:36.144371    4412 azuredisk.go:172] driver userAgent: disk.csi.azure.com/v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9 e2e-test
W1117 10:45:36.145869    4412 azure_disk_utils.go:229] get kubeconfig() failed with error: open /var/run/secrets/kubernetes.io/serviceaccount/token: The system cannot find the path specified.
I1117 10:45:36.146368    4412 azure_disk_utils.go:173] could not read cloud config from secret kube-system/azure-cloud-provider
I1117 10:45:36.146368    4412 azure_disk_utils.go:183] use default AZURE_CREDENTIAL_FILE env var: C:\k\azure.json
I1117 10:45:36.146368    4412 azure_disk_utils.go:191] read cloud config from file: C:\k\azure.json successfully
I1117 10:45:36.147370    4412 azure_auth.go:245] Using AzurePublicCloud environment
I1117 10:45:36.147866    4412 azure_auth.go:130] azure: using client_id+client_secret to retrieve access token
I1117 10:45:36.150873    4412 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02
... skipping 20 lines ...
I1117 10:45:36.394877    4412 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9"}
I1117 10:45:36.417867    4412 utils.go:77] GRPC call: /csi.v1.Identity/GetPluginInfo
I1117 10:45:36.417867    4412 utils.go:78] GRPC request: {}
I1117 10:45:36.418373    4412 utils.go:84] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.25.0-6b7ec56f9e2955e776323b54159120e3bde3deb9"}
I1117 10:45:36.995868    4412 utils.go:77] GRPC call: /csi.v1.Node/NodeGetInfo
I1117 10:45:36.995868    4412 utils.go:78] GRPC request: {}
I1117 10:45:37.022865    4412 azure_instance_metadata.go:139] Warning: failed to get loadbalancer metadata: failure of getting loadbalancer metadata with response "404 Not Found"
I1117 10:45:37.022865    4412 nodeserver.go:370] NodeGetInfo: nodeName(capz-qc09-44zcq), VM Size(Standard_D4s_v3)
I1117 10:45:37.022865    4412 nodeserver.go:408] got a matching size in getMaxDataDiskCount, VM Size: STANDARD_D4S_V3, MaxDataDiskCount: 8
I1117 10:45:37.022865    4412 utils.go:84] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.azure.com/zone":""}},"max_volumes_per_node":8,"node_id":"capz-qc09-44zcq"}
I1117 10:46:07.104630    4412 utils.go:77] GRPC call: /csi.v1.Identity/Probe
I1117 10:46:07.104630    4412 utils.go:78] GRPC request: {}
I1117 10:46:07.104630    4412 utils.go:84] GRPC response: {"ready":{"value":true}}
... skipping 1150 lines ...
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="300"} 35
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="600"} 35
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="1200"} 35
cloudprovider_azure_op_duration_seconds_bucket{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e",le="+Inf"} 35
cloudprovider_azure_op_duration_seconds_sum{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 549.2100935010001
cloudprovider_azure_op_duration_seconds_count{request="azuredisk_csi_driver_controller_unpublish_volume",resource_group="capz-qc0900",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="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 2
cloudprovider_azure_op_failure_count{request="azuredisk_csi_driver_controller_publish_volume",resource_group="capz-qc0900",source="disk.csi.azure.com",subscription_id="0e46bd28-a80f-4d3a-8200-d9eb8d80cb2e"} 1
# HELP go_gc_duration_seconds A summary of the pause duration of garbage collection cycles.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 3.0902e-05
... skipping 198 lines ...

JUnit report was created: /logs/artifacts/junit_01.xml


Summarizing 1 Failure:

[Fail] Dynamic Provisioning [single-az] [It] should create a pod, write to its pv, take a volume snapshot, overwrite data in original pv, create another pod from the snapshot, and read unaltered original data from original pv[disk.csi.azure.com] 
/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:825

Ran 22 of 62 Specs in 4414.690 seconds
FAIL! -- 21 Passed | 1 Failed | 0 Pending | 40 Skipped

You're using deprecated Ginkgo functionality:
=============================================
Ginkgo 2.0 is under active development and will introduce several new features, improvements, and a small handful of breaking changes.
A release candidate for 2.0 is now available and 2.0 should GA in Fall 2021.  Please give the RC a try and send us feedback!
  - To learn more, view the migration guide at https://github.com/onsi/ginkgo/blob/ver2/docs/MIGRATING_TO_V2.md
... skipping 5 lines ...
  If this change will be impactful to you please leave a comment on https://github.com/onsi/ginkgo/issues/711
  Learn more at: https://github.com/onsi/ginkgo/blob/ver2/docs/MIGRATING_TO_V2.md#removed-custom-reporters

To silence deprecations that can be silenced set the following environment variable:
  ACK_GINKGO_DEPRECATIONS=1.16.5

--- FAIL: TestE2E (4414.71s)
FAIL
FAIL	sigs.k8s.io/azuredisk-csi-driver/test/e2e	4414.772s
FAIL
make: *** [Makefile:261: e2e-test] Error 1
NAME                              STATUS   ROLES                  AGE   VERSION                           INTERNAL-IP   EXTERNAL-IP   OS-IMAGE                         KERNEL-VERSION     CONTAINER-RUNTIME
capz-qc09-44zcq                   Ready    <none>                 77m   v1.23.15-rc.0.11+2b8076aad0e0b8   10.1.0.5      <none>        Windows Server 2019 Datacenter   10.0.17763.3406    containerd://1.6.2
capz-qc09-p42ll                   Ready    <none>                 76m   v1.23.15-rc.0.11+2b8076aad0e0b8   10.1.0.4      <none>        Windows Server 2019 Datacenter   10.0.17763.3406    containerd://1.6.2
capz-qc0900-control-plane-2vwmb   Ready    control-plane,master   79m   v1.23.15-rc.0.11+2b8076aad0e0b8   10.0.0.4      <none>        Ubuntu 18.04.6 LTS               5.4.0-1091-azure   containerd://1.6.2
NAMESPACE     NAME                                                      READY   STATUS        RESTARTS      AGE     IP               NODE                              NOMINATED NODE   READINESS GATES
default       deployment-azuredisk-win-57859c58b4-6qg4b                 1/1     Running       0             2m23s   192.168.163.85   capz-qc09-p42ll                   <none>           <none>
... skipping 31 lines ...

Nov 17 11:49:28.800: INFO: Collecting logs for Windows node capz-qc09-44zcq in cluster capz-qc0900 in namespace default

Nov 17 11:50:57.278: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-qc09-44zcq to /logs/artifacts/clusters/capz-qc0900/machines/capz-qc0900-md-win-594567b59-4mbzt/crashdumps.tar
Nov 17 11:51:00.931: INFO: Collecting boot logs for AzureMachine capz-qc0900-md-win-44zcq

Failed to get logs for machine capz-qc0900-md-win-594567b59-4mbzt, cluster default/capz-qc0900: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1
Nov 17 11:51:02.341: INFO: Collecting logs for Windows node capz-qc09-p42ll in cluster capz-qc0900 in namespace default

Nov 17 11:52:45.849: INFO: Attempting to copy file /c:/crashdumps.tar on node capz-qc09-p42ll to /logs/artifacts/clusters/capz-qc0900/machines/capz-qc0900-md-win-594567b59-l8htk/crashdumps.tar
Nov 17 11:52:49.484: INFO: Collecting boot logs for AzureMachine capz-qc0900-md-win-p42ll

Failed to get logs for machine capz-qc0900-md-win-594567b59-l8htk, cluster default/capz-qc0900: running command "$p = 'c:\localdumps' ; if (Test-Path $p) { tar.exe -cvzf c:\crashdumps.tar $p *>&1 | %{ Write-Output "$_"} } else { Write-Host "No crash dumps found at $p" }": Process exited with status 1
STEP: Dumping workload cluster default/capz-qc0900 kube-system pod logs
STEP: Collecting events for Pod kube-system/calico-kube-controllers-85f479877b-kj2n9
STEP: Fetching kube-system pod logs took 1.157172169s
STEP: Dumping workload cluster default/capz-qc0900 Azure activity log
STEP: Collecting events for Pod kube-system/csi-proxy-mczjd
STEP: Creating log watcher for controller kube-system/containerd-logger-6djsx, container containerd-logger
STEP: Creating log watcher for controller kube-system/kube-proxy-dkxbq, container kube-proxy
STEP: Creating log watcher for controller kube-system/calico-node-windows-ndkk2, container calico-node-felix
STEP: failed to find events of Pod "calico-kube-controllers-85f479877b-kj2n9"
STEP: Creating log watcher for controller kube-system/calico-node-windows-xr2g7, container calico-node-startup
STEP: failed to find events of Pod "csi-proxy-mczjd"
STEP: Collecting events for Pod kube-system/containerd-logger-6djsx
STEP: Collecting events for Pod kube-system/etcd-capz-qc0900-control-plane-2vwmb
STEP: failed to find events of Pod "containerd-logger-6djsx"
STEP: Creating log watcher for controller kube-system/containerd-logger-gp67x, container containerd-logger
STEP: failed to find events of Pod "etcd-capz-qc0900-control-plane-2vwmb"
STEP: Creating log watcher for controller kube-system/csi-proxy-zs7rm, container csi-proxy
STEP: Collecting events for Pod kube-system/containerd-logger-gp67x
STEP: Creating log watcher for controller kube-system/coredns-64897985d-dd7kk, container coredns
STEP: Creating log watcher for controller kube-system/coredns-64897985d-k4t9v, container coredns
STEP: Creating log watcher for controller kube-system/etcd-capz-qc0900-control-plane-2vwmb, container etcd
STEP: Collecting events for Pod kube-system/coredns-64897985d-dd7kk
STEP: failed to find events of Pod "coredns-64897985d-dd7kk"
STEP: Collecting events for Pod kube-system/coredns-64897985d-k4t9v
STEP: failed to find events of Pod "coredns-64897985d-k4t9v"
STEP: Creating log watcher for controller kube-system/csi-proxy-mczjd, container csi-proxy
STEP: Collecting events for Pod kube-system/kube-proxy-windows-njt2c
STEP: failed to find events of Pod "kube-proxy-windows-njt2c"
STEP: Creating log watcher for controller kube-system/metrics-server-7bdcf69694-h747p, container metrics-server
STEP: Collecting events for Pod kube-system/kube-proxy-dkxbq
STEP: failed to find events of Pod "kube-proxy-dkxbq"
STEP: Creating log watcher for controller kube-system/kube-scheduler-capz-qc0900-control-plane-2vwmb, container kube-scheduler
STEP: Collecting events for Pod kube-system/metrics-server-7bdcf69694-h747p
STEP: failed to find events of Pod "metrics-server-7bdcf69694-h747p"
STEP: Creating log watcher for controller kube-system/calico-kube-controllers-85f479877b-kj2n9, container calico-kube-controllers
STEP: Collecting events for Pod kube-system/kube-proxy-windows-gsk6l
STEP: Collecting events for Pod kube-system/calico-node-windows-xr2g7
STEP: Collecting events for Pod kube-system/calico-node-fwk9r
STEP: failed to find events of Pod "kube-proxy-windows-gsk6l"
STEP: failed to find events of Pod "calico-node-windows-xr2g7"
STEP: failed to find events of Pod "calico-node-fwk9r"
STEP: Creating log watcher for controller kube-system/calico-node-windows-ndkk2, container calico-node-startup
STEP: Collecting events for Pod kube-system/kube-scheduler-capz-qc0900-control-plane-2vwmb
STEP: failed to find events of Pod "kube-scheduler-capz-qc0900-control-plane-2vwmb"
STEP: Collecting events for Pod kube-system/kube-apiserver-capz-qc0900-control-plane-2vwmb
STEP: failed to find events of Pod "kube-apiserver-capz-qc0900-control-plane-2vwmb"
STEP: Collecting events for Pod kube-system/csi-proxy-zs7rm
STEP: failed to find events of Pod "csi-proxy-zs7rm"
STEP: Collecting events for Pod kube-system/kube-controller-manager-capz-qc0900-control-plane-2vwmb
STEP: failed to find events of Pod "kube-controller-manager-capz-qc0900-control-plane-2vwmb"
STEP: Collecting events for Pod kube-system/calico-node-windows-ndkk2
STEP: failed to find events of Pod "containerd-logger-gp67x"
STEP: Creating log watcher for controller kube-system/kube-proxy-windows-gsk6l, container kube-proxy
STEP: Creating log watcher for controller kube-system/calico-node-fwk9r, container calico-node
STEP: failed to find events of Pod "calico-node-windows-ndkk2"
STEP: Creating log watcher for controller kube-system/kube-controller-manager-capz-qc0900-control-plane-2vwmb, container kube-controller-manager
STEP: Creating log watcher for controller kube-system/kube-proxy-windows-njt2c, container kube-proxy
STEP: Creating log watcher for controller kube-system/calico-node-windows-xr2g7, container calico-node-felix
STEP: Creating log watcher for controller kube-system/kube-apiserver-capz-qc0900-control-plane-2vwmb, container kube-apiserver
STEP: Fetching activity logs took 7.688551054s
================ REDACTING LOGS ================
... skipping 17 lines ...