This job view page is being replaced by Spyglass soon. Check out the new job view.
PRhccheng72: [V2] fix: prevent requesting replica attachment in a row for one volume
ResultABORTED
Tests 0 failed / 0 succeeded
Started2023-01-18 23:03
Elapsed1h21m
Revisiond8ba0aca670d0c02f92f6a79df1d42fdac692933
Refs 1693

No Test Failures!


Error lines from build-log.txt

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

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11345  100 11345    0     0   191k      0 --:--:-- --:--:-- --:--:--  191k
Downloading https://get.helm.sh/helm-v3.11.0-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull capzci.azurecr.io/azuredisk-csi:latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d || make container-all push-manifest
Error response from daemon: manifest for capzci.azurecr.io/azuredisk-csi:latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d not found: manifest unknown: manifest tagged by "latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d" 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=latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=e549890dfb2509639488eabe74ec6eabdacdbd4d -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-18T23:25:31Z -extldflags "-static"" -tags azurediskv2 -mod vendor -o _output/amd64/azurediskpluginv2.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 687 lines ...
         }
      }
   ]
}
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver'
docker pull capzci.azurecr.io/azdiskschedulerextender-csi:latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d || make azdiskschedulerextender-all push-manifest-azdiskschedulerextender
Error response from daemon: manifest for capzci.azurecr.io/azdiskschedulerextender-csi:latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d not found: manifest unknown: manifest tagged by "latest-v2-e549890dfb2509639488eabe74ec6eabdacdbd4d" is not found
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver'
docker buildx rm container-builder || true
container-builder removed
docker buildx create --use --name=container-builder
container-builder
# enable qemu for arm64 build
... skipping 1100 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 occurs 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 occurs 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 359 lines ...
            - volumeName
            - volume_context
            - volume_id
            type: object
          status:
            description: status represents the current state of AzVolumeAttachment.
              includes error, state, and attachment status Required
            properties:
              detail:
                description: Status summarizes the current attachment state of the
                  volume attachment Nil Status indicates that the volume has not yet
                  been attached to the node
                properties:
... skipping 7 lines ...
                  role:
                    description: The current attachment role.
                    type: string
                required:
                - role
                type: object
              error:
                description: Error occurred during attach/detach of volume
                properties:
                  code:
                    type: string
                  message:
                    type: string
                  parameters:
... skipping 90 lines ...
            - volumeName
            - volume_context
            - volume_id
            type: object
          status:
            description: status represents the current state of AzVolumeAttachment.
              includes error, state, and attachment status
            properties:
              annotation:
                additionalProperties:
                  type: string
                description: Annotations contains additional resource information
                  to guide driver actions
... skipping 13 lines ...
                  role:
                    description: The current attachment role.
                    type: string
                required:
                - role
                type: object
              error:
                description: Error occurred during attach/detach of volume
                properties:
                  code:
                    type: string
                  message:
                    type: string
                  parameters:
... skipping 169 lines ...
            - maxMountReplicaCount
            - volumeCapability
            - volumeName
            type: object
          status:
            description: status represents the current state of AzVolume. includes
              error, state, and volume status
            properties:
              detail:
                description: Current status detail of the AzVolume Nil detail indicates
                  that the volume has not been created
                properties:
                  accessible_topology:
... skipping 28 lines ...
                    type: string
                required:
                - capacity_bytes
                - node_expansion_required
                - volume_id
                type: object
              error:
                description: Error occurred during creation/deletion of volume
                properties:
                  code:
                    type: string
                  message:
                    type: string
                  parameters:
... skipping 154 lines ...
            - maxMountReplicaCount
            - volumeCapability
            - volumeName
            type: object
          status:
            description: status represents the current state of AzVolume. includes
              error, state, and volume status
            properties:
              annotation:
                additionalProperties:
                  type: string
                description: Annotations contains additional resource information
                  to guide driver actions
... skipping 34 lines ...
                    type: string
                required:
                - capacity_bytes
                - node_expansion_required
                - volume_id
                type: object
              error:
                description: Error occurred during creation/deletion of volume
                properties:
                  code:
                    type: string
                  message:
                    type: string
                  parameters:
... skipping 831 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 296 lines ...
Jan 18 23:35:21.105: INFO: PersistentVolumeClaim pvc-cqmth found but phase is Pending instead of Bound.
Jan 18 23:35:23.141: INFO: PersistentVolumeClaim pvc-cqmth found and phase=Bound (2.080757827s)
STEP: checking the PVC 01/18/23 23:35:23.141
STEP: validating provisioned PV 01/18/23 23:35:23.175
STEP: checking the PV 01/18/23 23:35:23.209
STEP: deploying the pod 01/18/23 23:35:23.209
STEP: checking that the pod's command exits with an error 01/18/23 23:35:23.257
Jan 18 23:35:23.257: INFO: Waiting up to 10m0s for pod "azuredisk-volume-tester-86qnd" in namespace "azuredisk-5077" to be "Error status code"
Jan 18 23:35:23.292: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 34.514141ms
Jan 18 23:35:25.327: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069299426s
Jan 18 23:35:27.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.070152373s
Jan 18 23:35:29.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.070375003s
Jan 18 23:35:31.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 8.070615286s
Jan 18 23:35:33.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 10.070748749s
... skipping 115 lines ...
Jan 18 23:39:25.329: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m2.071644857s
Jan 18 23:39:27.330: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m4.072954306s
Jan 18 23:39:29.329: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m6.071870328s
Jan 18 23:39:31.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m8.07097276s
Jan 18 23:39:33.330: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=false. Elapsed: 4m10.072206866s
Jan 18 23:39:35.330: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=false. Elapsed: 4m12.072830219s
Jan 18 23:39:37.329: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Failed", Reason="", readiness=false. Elapsed: 4m14.071467711s
STEP: Saw pod failure 01/18/23 23:39:37.329
Jan 18 23:39:37.329: INFO: Pod "azuredisk-volume-tester-86qnd" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message 01/18/23 23:39:37.33
Jan 18 23:39:37.419: INFO: deleting Pod "azuredisk-5077"/"azuredisk-volume-tester-86qnd"
Jan 18 23:39:37.460: INFO: Pod azuredisk-volume-tester-86qnd has the following logs: Out-File : Access to the path 'C:\mnt\test-1\data.txt' is denied.
At line:1 char:22
+ ... cho 'hello world' | Out-File -FilePath C:\mnt\test-1\data.txt; Get-Co ...
+                         ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
... skipping 56 lines ...
    Jan 18 23:35:21.105: INFO: PersistentVolumeClaim pvc-cqmth found but phase is Pending instead of Bound.
    Jan 18 23:35:23.141: INFO: PersistentVolumeClaim pvc-cqmth found and phase=Bound (2.080757827s)
    STEP: checking the PVC 01/18/23 23:35:23.141
    STEP: validating provisioned PV 01/18/23 23:35:23.175
    STEP: checking the PV 01/18/23 23:35:23.209
    STEP: deploying the pod 01/18/23 23:35:23.209
    STEP: checking that the pod's command exits with an error 01/18/23 23:35:23.257
    Jan 18 23:35:23.257: INFO: Waiting up to 10m0s for pod "azuredisk-volume-tester-86qnd" in namespace "azuredisk-5077" to be "Error status code"
    Jan 18 23:35:23.292: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 34.514141ms
    Jan 18 23:35:25.327: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069299426s
    Jan 18 23:35:27.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.070152373s
    Jan 18 23:35:29.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.070375003s
    Jan 18 23:35:31.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 8.070615286s
    Jan 18 23:35:33.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Pending", Reason="", readiness=false. Elapsed: 10.070748749s
... skipping 115 lines ...
    Jan 18 23:39:25.329: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m2.071644857s
    Jan 18 23:39:27.330: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m4.072954306s
    Jan 18 23:39:29.329: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m6.071870328s
    Jan 18 23:39:31.328: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=true. Elapsed: 4m8.07097276s
    Jan 18 23:39:33.330: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=false. Elapsed: 4m10.072206866s
    Jan 18 23:39:35.330: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Running", Reason="", readiness=false. Elapsed: 4m12.072830219s
    Jan 18 23:39:37.329: INFO: Pod "azuredisk-volume-tester-86qnd": Phase="Failed", Reason="", readiness=false. Elapsed: 4m14.071467711s
    STEP: Saw pod failure 01/18/23 23:39:37.329
    Jan 18 23:39:37.329: INFO: Pod "azuredisk-volume-tester-86qnd" satisfied condition "Error status code"
    STEP: checking that pod logs contain expected message 01/18/23 23:39:37.33
    Jan 18 23:39:37.419: INFO: deleting Pod "azuredisk-5077"/"azuredisk-volume-tester-86qnd"
    Jan 18 23:39:37.460: INFO: Pod azuredisk-volume-tester-86qnd 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 85 lines ...
Jan 18 23:40:24.575: INFO: PersistentVolumeClaim pvc-rvcc6 found and phase=Bound (2.070188481s)
STEP: checking the PVC 01/18/23 23:40:24.575
STEP: validating provisioned PV 01/18/23 23:40:24.608
STEP: checking the PV 01/18/23 23:40:24.641
STEP: attaching disk to node#0 01/18/23 23:40:24.689
STEP: deploying the pod 01/18/23 23:40:32.932
STEP: checking that the pod's command exits with no error 01/18/23 23:40:32.972
Jan 18 23:40:32.972: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-2c5qq" in namespace "azuredisk-2240" to be "Succeeded or Failed"
Jan 18 23:40:33.019: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 46.805933ms
Jan 18 23:40:35.054: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.081522218s
Jan 18 23:40:37.054: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08203578s
Jan 18 23:40:39.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.082535481s
Jan 18 23:40:41.053: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.080565872s
Jan 18 23:40:43.056: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.084479646s
... skipping 27 lines ...
Jan 18 23:41:39.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=true. Elapsed: 1m6.083497048s
Jan 18 23:41:41.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=true. Elapsed: 1m8.082591319s
Jan 18 23:41:43.056: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.083627193s
Jan 18 23:41:45.054: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=false. Elapsed: 1m12.082429876s
Jan 18 23:41:47.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m14.082895458s
STEP: Saw pod success 01/18/23 23:41:47.055
Jan 18 23:41:47.055: INFO: Pod "azuredisk-volume-tester-2c5qq" satisfied condition "Succeeded or Failed"
Jan 18 23:41:47.055: INFO: deleting Pod "azuredisk-2240"/"azuredisk-volume-tester-2c5qq"
Jan 18 23:41:47.111: INFO: Pod azuredisk-volume-tester-2c5qq has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-2c5qq in namespace azuredisk-2240 01/18/23 23:41:47.111
Jan 18 23:41:47.244: INFO: deleting PVC "azuredisk-2240"/"pvc-rvcc6"
Jan 18 23:41:47.244: INFO: Deleting PersistentVolumeClaim "pvc-rvcc6"
... skipping 38 lines ...
    Jan 18 23:40:24.575: INFO: PersistentVolumeClaim pvc-rvcc6 found and phase=Bound (2.070188481s)
    STEP: checking the PVC 01/18/23 23:40:24.575
    STEP: validating provisioned PV 01/18/23 23:40:24.608
    STEP: checking the PV 01/18/23 23:40:24.641
    STEP: attaching disk to node#0 01/18/23 23:40:24.689
    STEP: deploying the pod 01/18/23 23:40:32.932
    STEP: checking that the pod's command exits with no error 01/18/23 23:40:32.972
    Jan 18 23:40:32.972: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-2c5qq" in namespace "azuredisk-2240" to be "Succeeded or Failed"
    Jan 18 23:40:33.019: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 46.805933ms
    Jan 18 23:40:35.054: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.081522218s
    Jan 18 23:40:37.054: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.08203578s
    Jan 18 23:40:39.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.082535481s
    Jan 18 23:40:41.053: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.080565872s
    Jan 18 23:40:43.056: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.084479646s
... skipping 27 lines ...
    Jan 18 23:41:39.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=true. Elapsed: 1m6.083497048s
    Jan 18 23:41:41.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=true. Elapsed: 1m8.082591319s
    Jan 18 23:41:43.056: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=false. Elapsed: 1m10.083627193s
    Jan 18 23:41:45.054: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Running", Reason="", readiness=false. Elapsed: 1m12.082429876s
    Jan 18 23:41:47.055: INFO: Pod "azuredisk-volume-tester-2c5qq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m14.082895458s
    STEP: Saw pod success 01/18/23 23:41:47.055
    Jan 18 23:41:47.055: INFO: Pod "azuredisk-volume-tester-2c5qq" satisfied condition "Succeeded or Failed"
    Jan 18 23:41:47.055: INFO: deleting Pod "azuredisk-2240"/"azuredisk-volume-tester-2c5qq"
    Jan 18 23:41:47.111: INFO: Pod azuredisk-volume-tester-2c5qq has the following logs: hello world

    STEP: Deleting pod azuredisk-volume-tester-2c5qq in namespace azuredisk-2240 01/18/23 23:41:47.111
    Jan 18 23:41:47.244: INFO: deleting PVC "azuredisk-2240"/"pvc-rvcc6"
    Jan 18 23:41:47.244: INFO: Deleting PersistentVolumeClaim "pvc-rvcc6"
... skipping 152 lines ...
  << End Captured GinkgoWriter Output

  test case not supported by Windows clusters
  In [It] at: /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/utils/testutil/env_utils.go:26

  There were additional failures detected after the initial failure:
    [FAILED]
    pre-provisioning disk got deleted with the deletion of pv: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {
      "error": {

        "code": "NotFound",
        "message": "Disk single-shared-disk is not found."
      }
    }
    In [AfterEach] at: /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:490
------------------------------
... skipping 27 lines ...
  << End Captured GinkgoWriter Output

  test case not supported by Windows clusters
  In [It] at: /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/utils/testutil/env_utils.go:26

  There were additional failures detected after the initial failure:
    [FAILED]
    pre-provisioning disk got deleted with the deletion of pv: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {
      "error": {

        "code": "NotFound",
        "message": "Disk single-shared-disk is not found."
      }
    }
    In [AfterEach] at: /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:490
------------------------------
... skipping 27 lines ...
  << End Captured GinkgoWriter Output

  test case is only available for csi driver
  In [It] at: /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:395

  There were additional failures detected after the initial failure:
    [FAILED]
    pre-provisioning disk got deleted with the deletion of pv: Retriable: false, RetryAfter: 0s, HTTPStatusCode: 404, RawError: {
      "error": {

        "code": "NotFound",
        "message": "Disk single-shared-disk is not found."
      }
    }
    In [AfterEach] at: /home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning_test.go:490
------------------------------
... skipping 4 lines ...
Jan 18 23:42:39.480: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
STEP: Building a namespace api object, basename azuredisk 01/18/23 23:42:39.482
STEP: Waiting for a default service account to be provisioned in namespace 01/18/23 23:42:39.593
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace 01/18/23 23:42:39.657
I0118 23:42:39.722693   42032 azuredisk_driver.go:52] Using azure disk driver: disk.csi.azure.com
STEP: deploying the pod 01/18/23 23:42:39.769
STEP: checking that the pod's command exits with no error 01/18/23 23:42:39.809
Jan 18 23:42:39.810: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jckwt" in namespace "azuredisk-7325" to be "Succeeded or Failed"
Jan 18 23:42:39.843: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Pending", Reason="", readiness=false. Elapsed: 33.479476ms
Jan 18 23:42:41.877: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067375265s
Jan 18 23:42:43.876: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.066389824s
Jan 18 23:42:45.881: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=true. Elapsed: 6.071397057s
Jan 18 23:42:47.881: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=true. Elapsed: 8.071280396s
Jan 18 23:42:49.879: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=true. Elapsed: 10.069552926s
Jan 18 23:42:51.881: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=false. Elapsed: 12.071347235s
Jan 18 23:42:53.880: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.070354828s
STEP: Saw pod success 01/18/23 23:42:53.88
Jan 18 23:42:53.880: INFO: Pod "azuredisk-volume-tester-jckwt" satisfied condition "Succeeded or Failed"
Jan 18 23:42:53.880: INFO: deleting Pod "azuredisk-7325"/"azuredisk-volume-tester-jckwt"
Jan 18 23:42:53.930: INFO: Pod azuredisk-volume-tester-jckwt has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-jckwt in namespace azuredisk-7325 01/18/23 23:42:53.93
STEP: Destroying namespace "azuredisk-7325" for this suite. 01/18/23 23:42:53.975
------------------------------
... skipping 10 lines ...
    Jan 18 23:42:39.480: INFO: >>> kubeConfig: /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/kubeconfig
    STEP: Building a namespace api object, basename azuredisk 01/18/23 23:42:39.482
    STEP: Waiting for a default service account to be provisioned in namespace 01/18/23 23:42:39.593
    STEP: Waiting for kube-root-ca.crt to be provisioned in namespace 01/18/23 23:42:39.657
    I0118 23:42:39.722693   42032 azuredisk_driver.go:52] Using azure disk driver: disk.csi.azure.com
    STEP: deploying the pod 01/18/23 23:42:39.769
    STEP: checking that the pod's command exits with no error 01/18/23 23:42:39.809
    Jan 18 23:42:39.810: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-jckwt" in namespace "azuredisk-7325" to be "Succeeded or Failed"
    Jan 18 23:42:39.843: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Pending", Reason="", readiness=false. Elapsed: 33.479476ms
    Jan 18 23:42:41.877: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067375265s
    Jan 18 23:42:43.876: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Pending", Reason="", readiness=false. Elapsed: 4.066389824s
    Jan 18 23:42:45.881: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=true. Elapsed: 6.071397057s
    Jan 18 23:42:47.881: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=true. Elapsed: 8.071280396s
    Jan 18 23:42:49.879: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=true. Elapsed: 10.069552926s
    Jan 18 23:42:51.881: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Running", Reason="", readiness=false. Elapsed: 12.071347235s
    Jan 18 23:42:53.880: INFO: Pod "azuredisk-volume-tester-jckwt": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.070354828s
    STEP: Saw pod success 01/18/23 23:42:53.88
    Jan 18 23:42:53.880: INFO: Pod "azuredisk-volume-tester-jckwt" satisfied condition "Succeeded or Failed"
    Jan 18 23:42:53.880: INFO: deleting Pod "azuredisk-7325"/"azuredisk-volume-tester-jckwt"
    Jan 18 23:42:53.930: INFO: Pod azuredisk-volume-tester-jckwt has the following logs: hello world

    STEP: Deleting pod azuredisk-volume-tester-jckwt in namespace azuredisk-7325 01/18/23 23:42:53.93
    STEP: Destroying namespace "azuredisk-7325" for this suite. 01/18/23 23:42:53.975
  << End Captured GinkgoWriter Output
... skipping 17 lines ...
Jan 18 23:42:56.406: INFO: PersistentVolumeClaim pvc-l74w5 found but phase is Pending instead of Bound.
Jan 18 23:42:58.440: INFO: PersistentVolumeClaim pvc-l74w5 found and phase=Bound (4.104134127s)
STEP: checking the PVC 01/18/23 23:42:58.44
STEP: validating provisioned PV 01/18/23 23:42:58.473
STEP: checking the PV 01/18/23 23:42:58.506
STEP: deploying the pod 01/18/23 23:42:58.553
STEP: checking that the pod's command exits with no error 01/18/23 23:42:58.592
Jan 18 23:42:58.592: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rq4cw" in namespace "azuredisk-889" to be "Succeeded or Failed"
Jan 18 23:42:58.626: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 34.006394ms
Jan 18 23:43:00.663: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.071347279s
Jan 18 23:43:02.660: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.068530234s
Jan 18 23:43:04.659: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.067259356s
Jan 18 23:43:06.659: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.067670377s
Jan 18 23:43:08.659: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.067635013s
... skipping 19 lines ...
Jan 18 23:43:48.668: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=true. Elapsed: 50.075769906s
Jan 18 23:43:50.662: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=false. Elapsed: 52.070594127s
Jan 18 23:43:52.662: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=false. Elapsed: 54.070199387s
Jan 18 23:43:54.661: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=false. Elapsed: 56.069637732s
Jan 18 23:43:56.663: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.070884731s
STEP: Saw pod success 01/18/23 23:43:56.663
Jan 18 23:43:56.663: INFO: Pod "azuredisk-volume-tester-rq4cw" satisfied condition "Succeeded or Failed"
Jan 18 23:43:56.663: INFO: deleting Pod "azuredisk-889"/"azuredisk-volume-tester-rq4cw"
Jan 18 23:43:56.712: INFO: Pod azuredisk-volume-tester-rq4cw has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-rq4cw in namespace azuredisk-889 01/18/23 23:43:56.712
Jan 18 23:43:56.761: INFO: deleting PVC "azuredisk-889"/"pvc-l74w5"
Jan 18 23:43:56.761: INFO: Deleting PersistentVolumeClaim "pvc-l74w5"
... skipping 38 lines ...
    Jan 18 23:42:56.406: INFO: PersistentVolumeClaim pvc-l74w5 found but phase is Pending instead of Bound.
    Jan 18 23:42:58.440: INFO: PersistentVolumeClaim pvc-l74w5 found and phase=Bound (4.104134127s)
    STEP: checking the PVC 01/18/23 23:42:58.44
    STEP: validating provisioned PV 01/18/23 23:42:58.473
    STEP: checking the PV 01/18/23 23:42:58.506
    STEP: deploying the pod 01/18/23 23:42:58.553
    STEP: checking that the pod's command exits with no error 01/18/23 23:42:58.592
    Jan 18 23:42:58.592: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rq4cw" in namespace "azuredisk-889" to be "Succeeded or Failed"
    Jan 18 23:42:58.626: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 34.006394ms
    Jan 18 23:43:00.663: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.071347279s
    Jan 18 23:43:02.660: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.068530234s
    Jan 18 23:43:04.659: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.067259356s
    Jan 18 23:43:06.659: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.067670377s
    Jan 18 23:43:08.659: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Pending", Reason="", readiness=false. Elapsed: 10.067635013s
... skipping 19 lines ...
    Jan 18 23:43:48.668: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=true. Elapsed: 50.075769906s
    Jan 18 23:43:50.662: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=false. Elapsed: 52.070594127s
    Jan 18 23:43:52.662: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=false. Elapsed: 54.070199387s
    Jan 18 23:43:54.661: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Running", Reason="", readiness=false. Elapsed: 56.069637732s
    Jan 18 23:43:56.663: INFO: Pod "azuredisk-volume-tester-rq4cw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.070884731s
    STEP: Saw pod success 01/18/23 23:43:56.663
    Jan 18 23:43:56.663: INFO: Pod "azuredisk-volume-tester-rq4cw" satisfied condition "Succeeded or Failed"
    Jan 18 23:43:56.663: INFO: deleting Pod "azuredisk-889"/"azuredisk-volume-tester-rq4cw"
    Jan 18 23:43:56.712: INFO: Pod azuredisk-volume-tester-rq4cw has the following logs: hello world

    STEP: Deleting pod azuredisk-volume-tester-rq4cw in namespace azuredisk-889 01/18/23 23:43:56.712
    Jan 18 23:43:56.761: INFO: deleting PVC "azuredisk-889"/"pvc-l74w5"
    Jan 18 23:43:56.761: INFO: Deleting PersistentVolumeClaim "pvc-l74w5"
... skipping 195 lines ...
Jan 18 23:51:07.487: INFO: PersistentVolumeClaim pvc-c79dh found and phase=Bound (4.100129012s)
STEP: checking the PVC 01/18/23 23:51:07.487
STEP: validating provisioned PV 01/18/23 23:51:07.52
STEP: checking the PV 01/18/23 23:51:07.552
I0118 23:51:07.552985   42032 resource_setup.go:89] adding PV (pvc-c0b25777-fff7-408e-9981-226c0c90e282) to pod ()
STEP: deploying the pod 01/18/23 23:51:07.598
STEP: checking that the pod's command exits with no error 01/18/23 23:51:07.639
Jan 18 23:51:07.639: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5tg4m" in namespace "azuredisk-6016" to be "Succeeded or Failed"
Jan 18 23:51:07.671: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 32.598566ms
Jan 18 23:51:09.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0690635s
Jan 18 23:51:11.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.068005652s
Jan 18 23:51:13.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.069204298s
Jan 18 23:51:15.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.068774393s
Jan 18 23:51:17.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 10.068000433s
... skipping 24 lines ...
Jan 18 23:52:07.709: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.070616521s
Jan 18 23:52:09.710: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.070804407s
Jan 18 23:52:11.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m4.067989764s
Jan 18 23:52:13.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m6.0691145s
Jan 18 23:52:15.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m8.068055477s
STEP: Saw pod success 01/18/23 23:52:15.707
Jan 18 23:52:15.707: INFO: Pod "azuredisk-volume-tester-5tg4m" satisfied condition "Succeeded or Failed"
Jan 18 23:52:15.707: INFO: deleting Pod "azuredisk-6016"/"azuredisk-volume-tester-5tg4m"
Jan 18 23:52:15.776: INFO: Pod azuredisk-volume-tester-5tg4m has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-5tg4m in namespace azuredisk-6016 01/18/23 23:52:15.776
Jan 18 23:52:15.831: INFO: deleting PVC "azuredisk-6016"/"pvc-c79dh"
Jan 18 23:52:15.831: INFO: Deleting PersistentVolumeClaim "pvc-c79dh"
... skipping 85 lines ...
    Jan 18 23:51:07.487: INFO: PersistentVolumeClaim pvc-c79dh found and phase=Bound (4.100129012s)
    STEP: checking the PVC 01/18/23 23:51:07.487
    STEP: validating provisioned PV 01/18/23 23:51:07.52
    STEP: checking the PV 01/18/23 23:51:07.552
    I0118 23:51:07.552985   42032 resource_setup.go:89] adding PV (pvc-c0b25777-fff7-408e-9981-226c0c90e282) to pod ()
    STEP: deploying the pod 01/18/23 23:51:07.598
    STEP: checking that the pod's command exits with no error 01/18/23 23:51:07.639
    Jan 18 23:51:07.639: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5tg4m" in namespace "azuredisk-6016" to be "Succeeded or Failed"
    Jan 18 23:51:07.671: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 32.598566ms
    Jan 18 23:51:09.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0690635s
    Jan 18 23:51:11.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.068005652s
    Jan 18 23:51:13.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.069204298s
    Jan 18 23:51:15.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.068774393s
    Jan 18 23:51:17.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Pending", Reason="", readiness=false. Elapsed: 10.068000433s
... skipping 24 lines ...
    Jan 18 23:52:07.709: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.070616521s
    Jan 18 23:52:09.710: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m2.070804407s
    Jan 18 23:52:11.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m4.067989764s
    Jan 18 23:52:13.708: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Running", Reason="", readiness=false. Elapsed: 1m6.0691145s
    Jan 18 23:52:15.707: INFO: Pod "azuredisk-volume-tester-5tg4m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m8.068055477s
    STEP: Saw pod success 01/18/23 23:52:15.707
    Jan 18 23:52:15.707: INFO: Pod "azuredisk-volume-tester-5tg4m" satisfied condition "Succeeded or Failed"
    Jan 18 23:52:15.707: INFO: deleting Pod "azuredisk-6016"/"azuredisk-volume-tester-5tg4m"
    Jan 18 23:52:15.776: INFO: Pod azuredisk-volume-tester-5tg4m has the following logs: hello world

    STEP: Deleting pod azuredisk-volume-tester-5tg4m in namespace azuredisk-6016 01/18/23 23:52:15.776
    Jan 18 23:52:15.831: INFO: deleting PVC "azuredisk-6016"/"pvc-c79dh"
    Jan 18 23:52:15.831: INFO: Deleting PersistentVolumeClaim "pvc-c79dh"
... skipping 811 lines ...
STEP: checking the PVC 01/19/23 00:06:17.273
STEP: validating provisioned PV 01/19/23 00:06:17.306
STEP: checking the PV 01/19/23 00:06:17.34
STEP: setting up the pod 01/19/23 00:06:17.34
I0119 00:06:17.340374   42032 resource_setup.go:62] adding PV (pvc-a098b441-4be5-4eec-a3f2-7a252059496b) to pod ()
STEP: deploying the pod 01/19/23 00:06:17.34
STEP: checking that the pod's command exits with no error 01/19/23 00:06:17.382
Jan 19 00:06:17.382: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-slgnv" in namespace "azuredisk-1692" to be "Succeeded or Failed"
Jan 19 00:06:17.417: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 35.114177ms
Jan 19 00:06:19.452: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069615485s
Jan 19 00:06:21.453: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.070348152s
Jan 19 00:06:23.452: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.069311976s
Jan 19 00:06:25.455: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.07308957s
Jan 19 00:06:27.451: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.069221949s
... skipping 19 lines ...
Jan 19 00:07:07.454: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=true. Elapsed: 50.071452052s
Jan 19 00:07:09.454: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=false. Elapsed: 52.071371045s
Jan 19 00:07:11.453: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=false. Elapsed: 54.070798694s
Jan 19 00:07:13.454: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=false. Elapsed: 56.072048453s
Jan 19 00:07:15.455: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.072348468s
STEP: Saw pod success 01/19/23 00:07:15.455
Jan 19 00:07:15.455: INFO: Pod "azuredisk-volume-tester-slgnv" satisfied condition "Succeeded or Failed"
Jan 19 00:07:15.455: INFO: deleting Pod "azuredisk-1692"/"azuredisk-volume-tester-slgnv"
Jan 19 00:07:15.517: INFO: Pod azuredisk-volume-tester-slgnv has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-slgnv in namespace azuredisk-1692 01/19/23 00:07:15.517
Jan 19 00:07:15.564: INFO: deleting PVC "azuredisk-1692"/"pvc-tnzs9"
Jan 19 00:07:15.564: INFO: Deleting PersistentVolumeClaim "pvc-tnzs9"
... skipping 40 lines ...
    STEP: checking the PVC 01/19/23 00:06:17.273
    STEP: validating provisioned PV 01/19/23 00:06:17.306
    STEP: checking the PV 01/19/23 00:06:17.34
    STEP: setting up the pod 01/19/23 00:06:17.34
    I0119 00:06:17.340374   42032 resource_setup.go:62] adding PV (pvc-a098b441-4be5-4eec-a3f2-7a252059496b) to pod ()
    STEP: deploying the pod 01/19/23 00:06:17.34
    STEP: checking that the pod's command exits with no error 01/19/23 00:06:17.382
    Jan 19 00:06:17.382: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-slgnv" in namespace "azuredisk-1692" to be "Succeeded or Failed"
    Jan 19 00:06:17.417: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 35.114177ms
    Jan 19 00:06:19.452: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.069615485s
    Jan 19 00:06:21.453: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.070348152s
    Jan 19 00:06:23.452: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 6.069311976s
    Jan 19 00:06:25.455: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 8.07308957s
    Jan 19 00:06:27.451: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Pending", Reason="", readiness=false. Elapsed: 10.069221949s
... skipping 19 lines ...
    Jan 19 00:07:07.454: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=true. Elapsed: 50.071452052s
    Jan 19 00:07:09.454: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=false. Elapsed: 52.071371045s
    Jan 19 00:07:11.453: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=false. Elapsed: 54.070798694s
    Jan 19 00:07:13.454: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Running", Reason="", readiness=false. Elapsed: 56.072048453s
    Jan 19 00:07:15.455: INFO: Pod "azuredisk-volume-tester-slgnv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 58.072348468s
    STEP: Saw pod success 01/19/23 00:07:15.455
    Jan 19 00:07:15.455: INFO: Pod "azuredisk-volume-tester-slgnv" satisfied condition "Succeeded or Failed"
    Jan 19 00:07:15.455: INFO: deleting Pod "azuredisk-1692"/"azuredisk-volume-tester-slgnv"
    Jan 19 00:07:15.517: INFO: Pod azuredisk-volume-tester-slgnv has the following logs: hello world

    STEP: Deleting pod azuredisk-volume-tester-slgnv in namespace azuredisk-1692 01/19/23 00:07:15.517
    Jan 19 00:07:15.564: INFO: deleting PVC "azuredisk-1692"/"pvc-tnzs9"
    Jan 19 00:07:15.564: INFO: Deleting PersistentVolumeClaim "pvc-tnzs9"
... skipping 37 lines ...
Jan 19 00:07:58.752: INFO: PersistentVolumeClaim pvc-vf8pf found but phase is Pending instead of Bound.
Jan 19 00:08:00.786: INFO: PersistentVolumeClaim pvc-vf8pf found and phase=Bound (4.109825678s)
STEP: checking the PVC 01/19/23 00:08:00.786
STEP: validating provisioned PV 01/19/23 00:08:00.82
STEP: checking the PV 01/19/23 00:08:00.854
STEP: deploying the pod 01/19/23 00:08:00.854
STEP: checking that the pods command exits with no error 01/19/23 00:08:00.894
Jan 19 00:08:00.894: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rjz4t" in namespace "azuredisk-1416" to be "Succeeded or Failed"
Jan 19 00:08:00.931: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 36.612853ms
Jan 19 00:08:02.965: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 2.070683168s
Jan 19 00:08:04.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 4.071953684s
Jan 19 00:08:06.965: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 6.071042771s
Jan 19 00:08:08.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 8.071580708s
Jan 19 00:08:10.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 10.072387105s
... skipping 21 lines ...
Jan 19 00:08:54.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=true. Elapsed: 54.071562233s
Jan 19 00:08:56.965: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=false. Elapsed: 56.071403989s
Jan 19 00:08:58.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=false. Elapsed: 58.071923153s
Jan 19 00:09:00.968: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.073899351s
Jan 19 00:09:02.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m2.072192946s
STEP: Saw pod success 01/19/23 00:09:02.966
Jan 19 00:09:02.966: INFO: Pod "azuredisk-volume-tester-rjz4t" satisfied condition "Succeeded or Failed"
Jan 19 00:09:02.966: INFO: deleting Pod "azuredisk-1416"/"azuredisk-volume-tester-rjz4t"
Jan 19 00:09:03.029: INFO: Pod azuredisk-volume-tester-rjz4t has the following logs: hello world

STEP: Deleting pod azuredisk-volume-tester-rjz4t in namespace azuredisk-1416 01/19/23 00:09:03.029
Jan 19 00:09:03.085: INFO: deleting PVC "azuredisk-1416"/"pvc-vf8pf"
Jan 19 00:09:03.085: INFO: Deleting PersistentVolumeClaim "pvc-vf8pf"
... skipping 38 lines ...
    Jan 19 00:07:58.752: INFO: PersistentVolumeClaim pvc-vf8pf found but phase is Pending instead of Bound.
    Jan 19 00:08:00.786: INFO: PersistentVolumeClaim pvc-vf8pf found and phase=Bound (4.109825678s)
    STEP: checking the PVC 01/19/23 00:08:00.786
    STEP: validating provisioned PV 01/19/23 00:08:00.82
    STEP: checking the PV 01/19/23 00:08:00.854
    STEP: deploying the pod 01/19/23 00:08:00.854
    STEP: checking that the pods command exits with no error 01/19/23 00:08:00.894
    Jan 19 00:08:00.894: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rjz4t" in namespace "azuredisk-1416" to be "Succeeded or Failed"
    Jan 19 00:08:00.931: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 36.612853ms
    Jan 19 00:08:02.965: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 2.070683168s
    Jan 19 00:08:04.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 4.071953684s
    Jan 19 00:08:06.965: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 6.071042771s
    Jan 19 00:08:08.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 8.071580708s
    Jan 19 00:08:10.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Pending", Reason="", readiness=false. Elapsed: 10.072387105s
... skipping 21 lines ...
    Jan 19 00:08:54.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=true. Elapsed: 54.071562233s
    Jan 19 00:08:56.965: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=false. Elapsed: 56.071403989s
    Jan 19 00:08:58.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=false. Elapsed: 58.071923153s
    Jan 19 00:09:00.968: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Running", Reason="", readiness=false. Elapsed: 1m0.073899351s
    Jan 19 00:09:02.966: INFO: Pod "azuredisk-volume-tester-rjz4t": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m2.072192946s
    STEP: Saw pod success 01/19/23 00:09:02.966
    Jan 19 00:09:02.966: INFO: Pod "azuredisk-volume-tester-rjz4t" satisfied condition "Succeeded or Failed"
    Jan 19 00:09:02.966: INFO: deleting Pod "azuredisk-1416"/"azuredisk-volume-tester-rjz4t"
    Jan 19 00:09:03.029: INFO: Pod azuredisk-volume-tester-rjz4t has the following logs: hello world

    STEP: Deleting pod azuredisk-volume-tester-rjz4t in namespace azuredisk-1416 01/19/23 00:09:03.029
    Jan 19 00:09:03.085: INFO: deleting PVC "azuredisk-1416"/"pvc-vf8pf"
    Jan 19 00:09:03.085: INFO: Deleting PersistentVolumeClaim "pvc-vf8pf"
... skipping 39 lines ...
STEP: checking the PVC 01/19/23 00:09:48.364
STEP: validating provisioned PV 01/19/23 00:09:48.397
STEP: checking the PV 01/19/23 00:09:48.43
STEP: setting up the pod 01/19/23 00:09:48.43
I0119 00:09:48.430594   42032 resource_setup.go:62] adding PV (pvc-f9c30ae0-63b4-42ce-b4c4-8be11b5c0092) to pod ()
STEP: deploying the pod 01/19/23 00:09:48.43
STEP: checking that the pod's command exits with no error 01/19/23 00:09:48.469
Jan 19 00:09:48.469: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-dg5lz" in namespace "azuredisk-7093" to be "Succeeded or Failed"
Jan 19 00:09:48.504: INFO: Pod "azuredisk-volume-tester-dg5lz": Phase="Pending", Reason="", readiness=false. Elapsed: 34.181078ms
Jan 19 00:09:50.537: INFO: Pod "azuredisk-volume-tester-dg5lz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.0679207s
Jan 19 00:09:52.545: INFO: Pod "azuredisk-volume-tester-dg5lz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.075709781s
{"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:168","func":"k8s.io/test-infra/prow/entrypoint.Options.ExecuteProcess","level":"error","msg":"Entrypoint received interrupt: terminated","severity":"error","time":"2023-01-19T00:09:52Z"}
++ early_exit_handler
++ '[' -n 157 ']'
++ kill -TERM 157
++ cleanup_dind
++ [[ true == \t\r\u\e ]]
++ echo 'Cleaning up after docker'
... skipping 4 lines ...