This job view page is being replaced by Spyglass soon. Check out the new job view.

PR	alice-zheyan-yu: [V2] feat: fetch VMs to recover AzVolumeAttachment
Result	ABORTED
Tests	0 failed / 0 succeeded
Started	2023-01-20 18:43
Elapsed	56m14s
Revision	3c9841e0e8a2720e25692fb457a0736f981f613b
Refs	1666

• artifacts
• build log

No Test Failures!

---

Error lines from build-log.txt

• Expand Skipped Lines
• Raw build-log.txt

... skipping 244 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11345  100 11345    0     0   125k      0 --:--:-- --:--:-- --:--:--  125k
Downloading https://get.helm.sh/helm-v3.11.0-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull k8sprow.azurecr.io/azuredisk-csi:latest-v2-170b3ae022589c5c949eadbdc4736c1b28944228 || make container-all push-manifest
Error response from daemon: manifest for k8sprow.azurecr.io/azuredisk-csi:latest-v2-170b3ae022589c5c949eadbdc4736c1b28944228 not found: manifest unknown: manifest tagged by "latest-v2-170b3ae022589c5c949eadbdc4736c1b28944228" 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-170b3ae022589c5c949eadbdc4736c1b28944228 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=170b3ae022589c5c949eadbdc4736c1b28944228 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2023-01-20T18:48:02Z -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 680 lines ...
         }
      }
   ]
}
make[2]: Leaving directory '/home/prow/go/src/sigs.k8s.io/azuredisk-csi-driver'
docker pull k8sprow.azurecr.io/azdiskschedulerextender-csi:latest-v2-170b3ae022589c5c949eadbdc4736c1b28944228 || make azdiskschedulerextender-all push-manifest-azdiskschedulerextender
Error response from daemon: manifest for k8sprow.azurecr.io/azdiskschedulerextender-csi:latest-v2-170b3ae022589c5c949eadbdc4736c1b28944228 not found: manifest unknown: manifest tagged by "latest-v2-170b3ae022589c5c949eadbdc4736c1b28944228" 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 1047 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 1069 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 303 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Pre-provisioned PV (block volmode)] volumeMode
  test/e2e/storage/framework/testsuite.go:50
    should fail to use a volume in a pod with mismatched mode [Slow] [BeforeEach]
    test/e2e/storage/testsuites/volumemode.go:299

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 173 lines ...

    test/e2e/storage/framework/testsuite.go:127
------------------------------
SSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode 
  should fail to use a volume in a pod with mismatched mode [Slow]
  test/e2e/storage/testsuites/volumemode.go:299

[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
  test/e2e/framework/framework.go:187
... skipping 2 lines ...
STEP: Building a namespace api object, basename volumemode
W0120 18:58:35.605612   41400 warnings.go:70] policy/v1beta1 PodSecurityPolicy is deprecated in v1.21+, unavailable in v1.25+
Jan 20 18:58:35.605: INFO: Found PodSecurityPolicies; testing pod creation to see if PodSecurityPolicy is enabled
Jan 20 18:58:35.716: INFO: No PSP annotation exists on dry run pod; assuming PodSecurityPolicy is disabled
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
[It] should fail to use a volume in a pod with mismatched mode [Slow]
  test/e2e/storage/testsuites/volumemode.go:299
Jan 20 18:58:36.150: INFO: Creating resource for dynamic PV
Jan 20 18:58:36.150: INFO: Using claimSize:5Gi, test suite supported size:{ 1Mi}, driver(test.csi.azure.com) supported size:{ 1Mi} 
STEP: creating a StorageClass volumemode-6591-e2e-sc7kvqn
STEP: creating a claim
Jan 20 18:58:36.383: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comsp4rf] to have phase Bound
Jan 20 18:58:36.493: INFO: PersistentVolumeClaim test.csi.azure.comsp4rf found but phase is Pending instead of Bound.
Jan 20 18:58:38.601: INFO: PersistentVolumeClaim test.csi.azure.comsp4rf found but phase is Pending instead of Bound.
Jan 20 18:58:40.709: INFO: PersistentVolumeClaim test.csi.azure.comsp4rf found and phase=Bound (4.325501587s)
STEP: Creating pod
STEP: Waiting for the pod to fail
Jan 20 18:58:43.373: INFO: Deleting pod "pod-c2f23b87-231f-461d-bf63-b3bf94b81912" in namespace "volumemode-6591"
Jan 20 18:58:43.483: INFO: Wait up to 5m0s for pod "pod-c2f23b87-231f-461d-bf63-b3bf94b81912" to be fully deleted
STEP: Deleting pvc
Jan 20 18:58:45.737: INFO: Deleting PersistentVolumeClaim "test.csi.azure.comsp4rf"
Jan 20 18:58:45.846: INFO: Waiting up to 5m0s for PersistentVolume pvc-72a4badd-573f-4706-a5f8-00ee47def668 to get deleted
Jan 20 18:58:45.956: INFO: PersistentVolume pvc-72a4badd-573f-4706-a5f8-00ee47def668 found and phase=Released (109.64674ms)
... skipping 14 lines ...

• [SLOW TEST:52.203 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
  test/e2e/storage/framework/testsuite.go:50
    should fail to use a volume in a pod with mismatched mode [Slow]
    test/e2e/storage/testsuites/volumemode.go:299
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode should fail to use a volume in a pod with mismatched mode [Slow]","total":29,"completed":1,"skipped":107,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
Jan 20 18:59:27.423: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 41 lines ...
Jan 20 18:58:35.986: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comf94k6] to have phase Bound
Jan 20 18:58:36.095: INFO: PersistentVolumeClaim test.csi.azure.comf94k6 found but phase is Pending instead of Bound.
Jan 20 18:58:38.204: INFO: PersistentVolumeClaim test.csi.azure.comf94k6 found but phase is Pending instead of Bound.
Jan 20 18:58:40.313: INFO: PersistentVolumeClaim test.csi.azure.comf94k6 found and phase=Bound (4.326417852s)
STEP: Creating pod exec-volume-test-dynamicpv-8wcb
STEP: Creating a pod to test exec-volume-test
Jan 20 18:58:40.648: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-8wcb" in namespace "volume-5213" to be "Succeeded or Failed"
Jan 20 18:58:40.760: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 111.699398ms
Jan 20 18:58:42.886: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 2.237992342s
Jan 20 18:58:44.996: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 4.348086281s
Jan 20 18:58:47.105: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 6.456941003s
Jan 20 18:58:49.213: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 8.565460241s
Jan 20 18:58:51.323: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 10.67464447s
Jan 20 18:58:53.433: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 12.785114095s
Jan 20 18:58:55.542: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 14.894307263s
Jan 20 18:58:57.651: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 17.003138274s
Jan 20 18:58:59.761: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Pending", Reason="", readiness=false. Elapsed: 19.113018301s
Jan 20 18:59:01.871: INFO: Pod "exec-volume-test-dynamicpv-8wcb": Phase="Succeeded", Reason="", readiness=false. Elapsed: 21.222972899s
STEP: Saw pod success
Jan 20 18:59:01.871: INFO: Pod "exec-volume-test-dynamicpv-8wcb" satisfied condition "Succeeded or Failed"
Jan 20 18:59:01.979: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000001 pod exec-volume-test-dynamicpv-8wcb container exec-container-dynamicpv-8wcb: <nil>
STEP: delete the pod
Jan 20 18:59:02.234: INFO: Waiting for pod exec-volume-test-dynamicpv-8wcb to disappear
Jan 20 18:59:02.342: INFO: Pod exec-volume-test-dynamicpv-8wcb no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-8wcb
Jan 20 18:59:02.342: INFO: Deleting pod "exec-volume-test-dynamicpv-8wcb" in namespace "volume-5213"
... skipping 21 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] volumes
  test/e2e/storage/framework/testsuite.go:50
    should allow exec of files on the volume
    test/e2e/storage/testsuites/volumes.go:198
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes should allow exec of files on the volume","total":34,"completed":1,"skipped":30,"failed":0}

S
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy 
  (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with different fsgroup applied to the volume contents
  test/e2e/storage/testsuites/fsgroupchangepolicy.go:216
... skipping 116 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/storage/framework/testsuite.go:50
    (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with different fsgroup applied to the volume contents
    test/e2e/storage/testsuites/fsgroupchangepolicy.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with different fsgroup applied to the volume contents","total":42,"completed":1,"skipped":10,"failed":0}

SSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:00:00.609: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 3 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:242

    Distro debian doesn't support ntfs -- skipping

    test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 74 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  test/e2e/storage/framework/testsuite.go:50
    should support multiple inline ephemeral volumes
    test/e2e/storage/testsuites/ephemeral.go:254
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral should support multiple inline ephemeral volumes","total":35,"completed":1,"skipped":15,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support existing single file [LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:221
... skipping 20 lines ...
Jan 20 18:58:36.721: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com8crh5] to have phase Bound
Jan 20 18:58:36.829: INFO: PersistentVolumeClaim test.csi.azure.com8crh5 found but phase is Pending instead of Bound.
Jan 20 18:58:38.940: INFO: PersistentVolumeClaim test.csi.azure.com8crh5 found but phase is Pending instead of Bound.
Jan 20 18:58:41.053: INFO: PersistentVolumeClaim test.csi.azure.com8crh5 found and phase=Bound (4.332262871s)
STEP: Creating pod pod-subpath-test-dynamicpv-5s67
STEP: Creating a pod to test subpath
Jan 20 18:58:41.397: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-5s67" in namespace "provisioning-3701" to be "Succeeded or Failed"
Jan 20 18:58:41.506: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 108.883766ms
Jan 20 18:58:43.630: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 2.232228423s
Jan 20 18:58:45.739: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 4.341394918s
Jan 20 18:58:47.849: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 6.451826225s
Jan 20 18:58:49.961: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 8.563900441s
Jan 20 18:58:52.077: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 10.679742204s
Jan 20 18:58:54.186: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 12.78897933s
Jan 20 18:58:56.296: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 14.898424179s
Jan 20 18:58:58.406: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 17.008310155s
Jan 20 18:59:00.518: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 19.120398932s
Jan 20 18:59:02.633: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Pending", Reason="", readiness=false. Elapsed: 21.235156046s
Jan 20 18:59:04.742: INFO: Pod "pod-subpath-test-dynamicpv-5s67": Phase="Succeeded", Reason="", readiness=false. Elapsed: 23.344764158s
STEP: Saw pod success
Jan 20 18:59:04.742: INFO: Pod "pod-subpath-test-dynamicpv-5s67" satisfied condition "Succeeded or Failed"
Jan 20 18:59:04.851: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000001 pod pod-subpath-test-dynamicpv-5s67 container test-container-subpath-dynamicpv-5s67: <nil>
STEP: delete the pod
Jan 20 18:59:05.090: INFO: Waiting for pod pod-subpath-test-dynamicpv-5s67 to disappear
Jan 20 18:59:05.198: INFO: Pod pod-subpath-test-dynamicpv-5s67 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-5s67
Jan 20 18:59:05.198: INFO: Deleting pod "pod-subpath-test-dynamicpv-5s67" in namespace "provisioning-3701"
... skipping 33 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support existing single file [LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:221
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support existing single file [LinuxOnly]","total":24,"completed":1,"skipped":425,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] volumeIO
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:00:38.206: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 24 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:280

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 175 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] provisioning
  test/e2e/storage/framework/testsuite.go:50
    should provision storage with pvc data source
    test/e2e/storage/testsuites/provisioning.go:421
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] provisioning should provision storage with pvc data source","total":37,"completed":1,"skipped":9,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral 
  should create read-only inline ephemeral volume
  test/e2e/storage/testsuites/ephemeral.go:175
... skipping 45 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral
  test/e2e/storage/framework/testsuite.go:50
    should create read-only inline ephemeral volume
    test/e2e/storage/testsuites/ephemeral.go:175
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral should create read-only inline ephemeral volume","total":29,"completed":2,"skipped":172,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] provisioning
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:03:59.531: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 152 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the volume and restored snapshot from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
    test/e2e/storage/testsuites/multivolume.go:323
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] should concurrently access the volume and restored snapshot from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]","total":29,"completed":1,"skipped":55,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (ntfs)][Feature:Windows] volumes
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:04:26.308: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 156 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/storage/framework/testsuite.go:50
    (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents
    test/e2e/storage/testsuites/fsgroupchangepolicy.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents","total":35,"completed":2,"skipped":78,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:05:09.007: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 13 lines ...

    test/e2e/storage/external/external.go:262
------------------------------
S
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:280

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/framework/framework.go:187
STEP: Creating a kubernetes client
Jan 20 19:00:38.316: INFO: >>> kubeConfig: /root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json
STEP: Building a namespace api object, basename provisioning
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
[It] should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:280
Jan 20 19:00:39.069: INFO: Creating resource for dynamic PV
Jan 20 19:00:39.069: INFO: Using claimSize:5Gi, test suite supported size:{ 1Mi}, driver(test.csi.azure.com) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-2718-e2e-scfkv27
STEP: creating a claim
Jan 20 19:00:39.178: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Jan 20 19:00:39.288: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comdxsxh] to have phase Bound
Jan 20 19:00:39.396: INFO: PersistentVolumeClaim test.csi.azure.comdxsxh found but phase is Pending instead of Bound.
Jan 20 19:00:41.505: INFO: PersistentVolumeClaim test.csi.azure.comdxsxh found but phase is Pending instead of Bound.
Jan 20 19:00:43.614: INFO: PersistentVolumeClaim test.csi.azure.comdxsxh found and phase=Bound (4.325486205s)
STEP: Creating pod pod-subpath-test-dynamicpv-8fb5
STEP: Checking for subpath error in container status
Jan 20 19:01:02.170: INFO: Deleting pod "pod-subpath-test-dynamicpv-8fb5" in namespace "provisioning-2718"
Jan 20 19:01:02.279: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-8fb5" to be fully deleted
STEP: Deleting pod
Jan 20 19:01:04.496: INFO: Deleting pod "pod-subpath-test-dynamicpv-8fb5" in namespace "provisioning-2718"
STEP: Deleting pvc
Jan 20 19:01:04.604: INFO: Deleting PersistentVolumeClaim "test.csi.azure.comdxsxh"
... skipping 59 lines ...

• [SLOW TEST:287.672 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:280
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]","total":24,"completed":2,"skipped":553,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:05:26.016: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 3 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath file is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:258

    Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 22 lines ...
Jan 20 18:59:45.103: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comm2kfj] to have phase Bound
Jan 20 18:59:45.211: INFO: PersistentVolumeClaim test.csi.azure.comm2kfj found but phase is Pending instead of Bound.
Jan 20 18:59:47.321: INFO: PersistentVolumeClaim test.csi.azure.comm2kfj found but phase is Pending instead of Bound.
Jan 20 18:59:49.430: INFO: PersistentVolumeClaim test.csi.azure.comm2kfj found and phase=Bound (4.326688534s)
STEP: Creating pod pod-subpath-test-dynamicpv-brls
STEP: Creating a pod to test subpath
Jan 20 18:59:49.768: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-brls" in namespace "provisioning-4583" to be "Succeeded or Failed"
Jan 20 18:59:49.877: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 108.382036ms
Jan 20 18:59:51.987: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 2.21843463s
Jan 20 18:59:54.104: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 4.336023426s
Jan 20 18:59:56.216: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 6.448018595s
Jan 20 18:59:58.326: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 8.55745768s
Jan 20 19:00:00.435: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 10.666890638s
... skipping 26 lines ...
Jan 20 19:00:57.437: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 1m7.668879351s
Jan 20 19:00:59.548: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 1m9.779115152s
Jan 20 19:01:01.657: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 1m11.88821012s
Jan 20 19:01:03.802: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Pending", Reason="", readiness=false. Elapsed: 1m14.033700848s
Jan 20 19:01:05.918: INFO: Pod "pod-subpath-test-dynamicpv-brls": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m16.149600362s
STEP: Saw pod success
Jan 20 19:01:05.918: INFO: Pod "pod-subpath-test-dynamicpv-brls" satisfied condition "Succeeded or Failed"
Jan 20 19:01:06.038: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000001 pod pod-subpath-test-dynamicpv-brls container test-container-subpath-dynamicpv-brls: <nil>
STEP: delete the pod
Jan 20 19:01:06.299: INFO: Waiting for pod pod-subpath-test-dynamicpv-brls to disappear
Jan 20 19:01:06.407: INFO: Pod pod-subpath-test-dynamicpv-brls no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-brls
Jan 20 19:01:06.407: INFO: Deleting pod "pod-subpath-test-dynamicpv-brls" in namespace "provisioning-4583"
... skipping 66 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support readOnly file specified in the volumeMount [LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:382
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support readOnly file specified in the volumeMount [LinuxOnly]","total":34,"completed":2,"skipped":31,"failed":0}

SSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:05:28.035: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 68 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] volumeIO
  test/e2e/storage/framework/testsuite.go:50
    should write files of various sizes, verify size, validate content [Slow]
    test/e2e/storage/testsuites/volume_io.go:149
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumeIO should write files of various sizes, verify size, validate content [Slow]","total":29,"completed":3,"skipped":223,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] volumeMode
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:05:36.650: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 24 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:242

    Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 283 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] provisioning
  test/e2e/storage/framework/testsuite.go:50
    should provision storage with pvc data source
    test/e2e/storage/testsuites/provisioning.go:421
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] provisioning should provision storage with pvc data source","total":42,"completed":2,"skipped":55,"failed":0}

SSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] 
  should concurrently access the single read-only volume from pods on the same node
  test/e2e/storage/testsuites/multivolume.go:423
... skipping 81 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single read-only volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:423
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] should concurrently access the single read-only volume from pods on the same node","total":35,"completed":3,"skipped":118,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
... skipping 237 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the volume and restored snapshot from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
    test/e2e/storage/testsuites/multivolume.go:323
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should concurrently access the volume and restored snapshot from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]","total":37,"completed":2,"skipped":56,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (ext3)] volumes
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:07:04.494: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 236 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should access to two volumes with the same volume mode and retain data across pod recreation on different node
    test/e2e/storage/testsuites/multivolume.go:168
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] should access to two volumes with the same volume mode and retain data across pod recreation on different node","total":29,"completed":2,"skipped":139,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support non-existent path
  test/e2e/storage/testsuites/subpath.go:196
... skipping 17 lines ...
Jan 20 19:05:39.930: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comk4g2z] to have phase Bound
Jan 20 19:05:40.038: INFO: PersistentVolumeClaim test.csi.azure.comk4g2z found but phase is Pending instead of Bound.
Jan 20 19:05:42.146: INFO: PersistentVolumeClaim test.csi.azure.comk4g2z found but phase is Pending instead of Bound.
Jan 20 19:05:44.255: INFO: PersistentVolumeClaim test.csi.azure.comk4g2z found and phase=Bound (4.325164313s)
STEP: Creating pod pod-subpath-test-dynamicpv-flm9
STEP: Creating a pod to test subpath
Jan 20 19:05:44.591: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-flm9" in namespace "provisioning-7748" to be "Succeeded or Failed"
Jan 20 19:05:44.699: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 108.095279ms
Jan 20 19:05:46.809: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217761792s
Jan 20 19:05:48.918: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.327240185s
Jan 20 19:05:51.027: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.436040531s
Jan 20 19:05:53.136: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.544776434s
Jan 20 19:05:55.244: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 10.652741796s
... skipping 6 lines ...
Jan 20 19:06:10.016: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 25.424778666s
Jan 20 19:06:12.124: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 27.533146352s
Jan 20 19:06:14.233: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 29.641496885s
Jan 20 19:06:16.341: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Pending", Reason="", readiness=false. Elapsed: 31.750127355s
Jan 20 19:06:18.453: INFO: Pod "pod-subpath-test-dynamicpv-flm9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 33.862268216s
STEP: Saw pod success
Jan 20 19:06:18.454: INFO: Pod "pod-subpath-test-dynamicpv-flm9" satisfied condition "Succeeded or Failed"
Jan 20 19:06:18.561: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000001 pod pod-subpath-test-dynamicpv-flm9 container test-container-volume-dynamicpv-flm9: <nil>
STEP: delete the pod
Jan 20 19:06:18.814: INFO: Waiting for pod pod-subpath-test-dynamicpv-flm9 to disappear
Jan 20 19:06:18.921: INFO: Pod pod-subpath-test-dynamicpv-flm9 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-flm9
Jan 20 19:06:18.922: INFO: Deleting pod "pod-subpath-test-dynamicpv-flm9" in namespace "provisioning-7748"
... skipping 29 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support non-existent path
    test/e2e/storage/testsuites/subpath.go:196
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support non-existent path","total":29,"completed":4,"skipped":501,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Pre-provisioned Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
... skipping 141 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single read-only volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:423
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should concurrently access the single read-only volume from pods on the same node","total":24,"completed":3,"skipped":589,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (ext4)] volumes
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:08:26.610: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 256 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:298
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] should concurrently access the single volume from pods on the same node","total":29,"completed":3,"skipped":218,"failed":0}

SSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:08:52.132: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 70 lines ...
Jan 20 19:07:05.541: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com58t74] to have phase Bound
Jan 20 19:07:05.664: INFO: PersistentVolumeClaim test.csi.azure.com58t74 found but phase is Pending instead of Bound.
Jan 20 19:07:07.773: INFO: PersistentVolumeClaim test.csi.azure.com58t74 found but phase is Pending instead of Bound.
Jan 20 19:07:09.882: INFO: PersistentVolumeClaim test.csi.azure.com58t74 found and phase=Bound (4.3408502s)
STEP: Creating pod pod-subpath-test-dynamicpv-dqhl
STEP: Creating a pod to test subpath
Jan 20 19:07:10.212: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-dqhl" in namespace "provisioning-5213" to be "Succeeded or Failed"
Jan 20 19:07:10.323: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 110.254902ms
Jan 20 19:07:12.432: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.21954599s
Jan 20 19:07:14.542: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.329079955s
Jan 20 19:07:16.652: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.439293685s
Jan 20 19:07:18.762: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.549329308s
Jan 20 19:07:20.871: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 10.65867358s
... skipping 10 lines ...
Jan 20 19:07:44.105: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 33.892521869s
Jan 20 19:07:46.215: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 36.002232678s
Jan 20 19:07:48.324: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 38.111881322s
Jan 20 19:07:50.434: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Pending", Reason="", readiness=false. Elapsed: 40.221833708s
Jan 20 19:07:52.545: INFO: Pod "pod-subpath-test-dynamicpv-dqhl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.332445266s
STEP: Saw pod success
Jan 20 19:07:52.545: INFO: Pod "pod-subpath-test-dynamicpv-dqhl" satisfied condition "Succeeded or Failed"
Jan 20 19:07:52.654: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000001 pod pod-subpath-test-dynamicpv-dqhl container test-container-volume-dynamicpv-dqhl: <nil>
STEP: delete the pod
Jan 20 19:07:52.906: INFO: Waiting for pod pod-subpath-test-dynamicpv-dqhl to disappear
Jan 20 19:07:53.015: INFO: Pod pod-subpath-test-dynamicpv-dqhl no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-dqhl
Jan 20 19:07:53.015: INFO: Deleting pod "pod-subpath-test-dynamicpv-dqhl" in namespace "provisioning-5213"
... skipping 29 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support existing directory
    test/e2e/storage/testsuites/subpath.go:207
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support existing directory","total":37,"completed":3,"skipped":103,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:09:05.647: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 159 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if non-existent subpath is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:269

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 246 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should access to two volumes with different volume mode and retain data across pod recreation on the same node
    test/e2e/storage/testsuites/multivolume.go:209
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] should access to two volumes with different volume mode and retain data across pod recreation on the same node","total":35,"completed":4,"skipped":265,"failed":0}

SSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:09:15.932: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 59 lines ...
Jan 20 19:05:29.027: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com4wpbn] to have phase Bound
Jan 20 19:05:29.135: INFO: PersistentVolumeClaim test.csi.azure.com4wpbn found but phase is Pending instead of Bound.
Jan 20 19:05:31.245: INFO: PersistentVolumeClaim test.csi.azure.com4wpbn found but phase is Pending instead of Bound.
Jan 20 19:05:33.354: INFO: PersistentVolumeClaim test.csi.azure.com4wpbn found and phase=Bound (4.32664209s)
STEP: [init] starting a pod to use the claim
STEP: [init] check pod success
Jan 20 19:05:33.789: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-vl6r7" in namespace "snapshotting-645" to be "Succeeded or Failed"
Jan 20 19:05:33.897: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 108.026192ms
Jan 20 19:05:36.007: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217842177s
Jan 20 19:05:38.119: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.329589927s
Jan 20 19:05:40.232: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.442889337s
Jan 20 19:05:42.342: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.552487516s
Jan 20 19:05:44.451: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 10.661610306s
... skipping 11 lines ...
Jan 20 19:06:09.765: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 35.976201352s
Jan 20 19:06:11.874: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 38.084812992s
Jan 20 19:06:13.983: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 40.193892242s
Jan 20 19:06:16.098: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Pending", Reason="", readiness=false. Elapsed: 42.308376562s
Jan 20 19:06:18.207: INFO: Pod "pvc-snapshottable-tester-vl6r7": Phase="Succeeded", Reason="", readiness=false. Elapsed: 44.417480742s
STEP: Saw pod success
Jan 20 19:06:18.207: INFO: Pod "pvc-snapshottable-tester-vl6r7" satisfied condition "Succeeded or Failed"
STEP: [init] checking the claim
Jan 20 19:06:18.315: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com4wpbn] to have phase Bound
Jan 20 19:06:18.423: INFO: PersistentVolumeClaim test.csi.azure.com4wpbn found and phase=Bound (108.011373ms)
STEP: [init] checking the PV
STEP: [init] deleting the pod
Jan 20 19:06:18.775: INFO: Pod pvc-snapshottable-tester-vl6r7 has the following logs: 
... skipping 34 lines ...
Jan 20 19:06:29.413: INFO: WaitUntil finished successfully after 108.505647ms
STEP: getting the snapshot and snapshot content
STEP: checking the snapshot
STEP: checking the SnapshotContent
STEP: Modifying source data test
STEP: modifying the data in the source PVC
Jan 20 19:06:29.958: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-data-tester-s4sng" in namespace "snapshotting-645" to be "Succeeded or Failed"
Jan 20 19:06:30.066: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 108.203566ms
Jan 20 19:06:32.176: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218170362s
Jan 20 19:06:34.286: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 4.328293695s
Jan 20 19:06:36.400: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 6.442403952s
Jan 20 19:06:38.510: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 8.552446085s
Jan 20 19:06:40.620: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 10.661997018s
... skipping 20 lines ...
Jan 20 19:07:24.937: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 54.979634141s
Jan 20 19:07:27.046: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 57.088742559s
Jan 20 19:07:29.156: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 59.198537658s
Jan 20 19:07:31.266: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Pending", Reason="", readiness=false. Elapsed: 1m1.308195431s
Jan 20 19:07:33.375: INFO: Pod "pvc-snapshottable-data-tester-s4sng": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m3.417167828s
STEP: Saw pod success
Jan 20 19:07:33.375: INFO: Pod "pvc-snapshottable-data-tester-s4sng" satisfied condition "Succeeded or Failed"
Jan 20 19:07:33.626: INFO: Pod pvc-snapshottable-data-tester-s4sng has the following logs: 
Jan 20 19:07:33.627: INFO: Deleting pod "pvc-snapshottable-data-tester-s4sng" in namespace "snapshotting-645"
Jan 20 19:07:33.742: INFO: Wait up to 5m0s for pod "pvc-snapshottable-data-tester-s4sng" to be fully deleted
STEP: creating a pvc from the snapshot
STEP: starting a pod to use the snapshot
Jan 20 19:08:50.297: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uyqkadau.westeurope.cloudapp.azure.com --kubeconfig=/root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json --namespace=snapshotting-645 exec restored-pvc-tester-m2sf8 --namespace=snapshotting-645 -- cat /mnt/test/data'
... skipping 33 lines ...
Jan 20 19:09:16.569: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
Jan 20 19:09:17.678: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
Jan 20 19:09:18.788: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
Jan 20 19:09:19.898: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
Jan 20 19:09:21.010: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
Jan 20 19:09:22.126: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
Jan 20 19:09:23.127: INFO: WaitUntil failed after reaching the timeout 30s
[AfterEach] volume snapshot controller
  test/e2e/storage/testsuites/snapshottable.go:172
Jan 20 19:09:23.236: INFO: Error getting logs for pod restored-pvc-tester-m2sf8: the server could not find the requested resource (get pods restored-pvc-tester-m2sf8)
Jan 20 19:09:23.236: INFO: Deleting pod "restored-pvc-tester-m2sf8" in namespace "snapshotting-645"
Jan 20 19:09:23.344: INFO: deleting claim "snapshotting-645"/"pvc-22tgw"
Jan 20 19:09:23.454: INFO: deleting snapshot "snapshotting-645"/"pre-provisioned-snapshot-4f8466f5-415c-42d2-bc47-fe18dd7c4b62"
Jan 20 19:09:23.570: INFO: deleting snapshot content "pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62"
Jan 20 19:09:23.908: INFO: Waiting up to 5m0s for volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 to be deleted
Jan 20 19:09:24.017: INFO: volumesnapshotcontents pre-provisioned-snapcontent-4f8466f5-415c-42d2-bc47-fe18dd7c4b62 has been found and is not deleted
... skipping 27 lines ...
    test/e2e/storage/testsuites/snapshottable.go:113
      
      test/e2e/storage/testsuites/snapshottable.go:176
        should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)
        test/e2e/storage/testsuites/snapshottable.go:278
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Pre-provisioned Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)","total":34,"completed":3,"skipped":66,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support existing directories when readOnly specified in the volumeSource
  test/e2e/storage/testsuites/subpath.go:397
... skipping 17 lines ...
Jan 20 19:07:33.515: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comxfngg] to have phase Bound
Jan 20 19:07:33.623: INFO: PersistentVolumeClaim test.csi.azure.comxfngg found but phase is Pending instead of Bound.
Jan 20 19:07:35.731: INFO: PersistentVolumeClaim test.csi.azure.comxfngg found but phase is Pending instead of Bound.
Jan 20 19:07:37.841: INFO: PersistentVolumeClaim test.csi.azure.comxfngg found and phase=Bound (4.326070582s)
STEP: Creating pod pod-subpath-test-dynamicpv-8k5k
STEP: Creating a pod to test subpath
Jan 20 19:07:38.176: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-8k5k" in namespace "provisioning-6141" to be "Succeeded or Failed"
Jan 20 19:07:38.288: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 112.040223ms
Jan 20 19:07:40.398: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.222125975s
Jan 20 19:07:42.510: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.333890828s
Jan 20 19:07:44.620: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.44429877s
Jan 20 19:07:46.730: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.553595708s
Jan 20 19:07:48.843: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.666683538s
... skipping 10 lines ...
Jan 20 19:08:12.053: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 33.877115221s
Jan 20 19:08:14.162: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 35.985823838s
Jan 20 19:08:16.271: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 38.095368408s
Jan 20 19:08:18.381: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 40.205436828s
Jan 20 19:08:20.491: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 42.314866301s
STEP: Saw pod success
Jan 20 19:08:20.491: INFO: Pod "pod-subpath-test-dynamicpv-8k5k" satisfied condition "Succeeded or Failed"
Jan 20 19:08:20.600: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000002 pod pod-subpath-test-dynamicpv-8k5k container test-container-subpath-dynamicpv-8k5k: <nil>
STEP: delete the pod
Jan 20 19:08:20.872: INFO: Waiting for pod pod-subpath-test-dynamicpv-8k5k to disappear
Jan 20 19:08:20.980: INFO: Pod pod-subpath-test-dynamicpv-8k5k no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-8k5k
Jan 20 19:08:20.980: INFO: Deleting pod "pod-subpath-test-dynamicpv-8k5k" in namespace "provisioning-6141"
STEP: Creating pod pod-subpath-test-dynamicpv-8k5k
STEP: Creating a pod to test subpath
Jan 20 19:08:21.202: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-8k5k" in namespace "provisioning-6141" to be "Succeeded or Failed"
Jan 20 19:08:21.311: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 108.900388ms
Jan 20 19:08:23.420: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217950098s
Jan 20 19:08:25.530: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.327641257s
Jan 20 19:08:27.640: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.437219045s
Jan 20 19:08:29.750: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.54702083s
Jan 20 19:08:31.859: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.656346627s
... skipping 20 lines ...
Jan 20 19:09:16.177: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 54.974710926s
Jan 20 19:09:18.287: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Pending", Reason="", readiness=false. Elapsed: 57.084877568s
Jan 20 19:09:20.397: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Running", Reason="", readiness=true. Elapsed: 59.194739362s
Jan 20 19:09:22.507: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Running", Reason="", readiness=false. Elapsed: 1m1.304066473s
Jan 20 19:09:24.618: INFO: Pod "pod-subpath-test-dynamicpv-8k5k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m3.415166543s
STEP: Saw pod success
Jan 20 19:09:24.618: INFO: Pod "pod-subpath-test-dynamicpv-8k5k" satisfied condition "Succeeded or Failed"
Jan 20 19:09:24.726: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000001 pod pod-subpath-test-dynamicpv-8k5k container test-container-subpath-dynamicpv-8k5k: <nil>
STEP: delete the pod
Jan 20 19:09:24.976: INFO: Waiting for pod pod-subpath-test-dynamicpv-8k5k to disappear
Jan 20 19:09:25.084: INFO: Pod pod-subpath-test-dynamicpv-8k5k no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-8k5k
Jan 20 19:09:25.085: INFO: Deleting pod "pod-subpath-test-dynamicpv-8k5k" in namespace "provisioning-6141"
... skipping 23 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support existing directories when readOnly specified in the volumeSource
    test/e2e/storage/testsuites/subpath.go:397
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support existing directories when readOnly specified in the volumeSource","total":29,"completed":5,"skipped":617,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:10:06.977: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 38 lines ...
Jan 20 19:08:54.131: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comsjn9s] to have phase Bound
Jan 20 19:08:54.239: INFO: PersistentVolumeClaim test.csi.azure.comsjn9s found but phase is Pending instead of Bound.
Jan 20 19:08:56.348: INFO: PersistentVolumeClaim test.csi.azure.comsjn9s found but phase is Pending instead of Bound.
Jan 20 19:08:58.456: INFO: PersistentVolumeClaim test.csi.azure.comsjn9s found and phase=Bound (4.325633811s)
STEP: Creating pod pod-subpath-test-dynamicpv-4cvz
STEP: Creating a pod to test multi_subpath
Jan 20 19:08:58.782: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-4cvz" in namespace "provisioning-5083" to be "Succeeded or Failed"
Jan 20 19:08:58.892: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 109.159919ms
Jan 20 19:09:01.002: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219309234s
Jan 20 19:09:03.112: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.329369477s
Jan 20 19:09:05.222: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.439243866s
Jan 20 19:09:07.331: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.548800768s
Jan 20 19:09:09.442: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.659802089s
... skipping 4 lines ...
Jan 20 19:09:19.999: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 21.217007049s
Jan 20 19:09:22.120: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 23.337945101s
Jan 20 19:09:24.246: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 25.464034699s
Jan 20 19:09:26.358: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Pending", Reason="", readiness=false. Elapsed: 27.575796948s
Jan 20 19:09:28.468: INFO: Pod "pod-subpath-test-dynamicpv-4cvz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 29.685845235s
STEP: Saw pod success
Jan 20 19:09:28.468: INFO: Pod "pod-subpath-test-dynamicpv-4cvz" satisfied condition "Succeeded or Failed"
Jan 20 19:09:28.576: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000002 pod pod-subpath-test-dynamicpv-4cvz container test-container-subpath-dynamicpv-4cvz: <nil>
STEP: delete the pod
Jan 20 19:09:28.808: INFO: Waiting for pod pod-subpath-test-dynamicpv-4cvz to disappear
Jan 20 19:09:28.916: INFO: Pod pod-subpath-test-dynamicpv-4cvz no longer exists
STEP: Deleting pod
Jan 20 19:09:28.916: INFO: Deleting pod "pod-subpath-test-dynamicpv-4cvz" in namespace "provisioning-5083"
... skipping 21 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support creating multiple subpath from same volumes [Slow]
    test/e2e/storage/testsuites/subpath.go:296
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support creating multiple subpath from same volumes [Slow]","total":29,"completed":4,"skipped":253,"failed":0}

SSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
... skipping 172 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/storage/framework/testsuite.go:50
    (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with same fsgroup skips ownership changes to the volume contents
    test/e2e/storage/testsuites/fsgroupchangepolicy.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with same fsgroup skips ownership changes to the volume contents","total":24,"completed":4,"skipped":801,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:10:16.183: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 355 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] provisioning
  test/e2e/storage/framework/testsuite.go:50
    should provision storage with pvc data source in parallel [Slow]
    test/e2e/storage/testsuites/provisioning.go:459
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] provisioning should provision storage with pvc data source in parallel [Slow]","total":42,"completed":3,"skipped":68,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:10:47.553: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 58 lines ...
  test/e2e/framework/framework.go:188
Jan 20 19:10:48.826: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "volumelimits-1793" for this suite.

•
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] volumeLimits should verify that all csinodes have volume limits","total":42,"completed":4,"skipped":181,"failed":0}

SSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support restarting containers using file as subpath [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:333
... skipping 65 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support restarting containers using file as subpath [Slow][LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:333
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support restarting containers using file as subpath [Slow][LinuxOnly]","total":37,"completed":4,"skipped":437,"failed":0}

SSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:11:59.026: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 149 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] provisioning
  test/e2e/storage/framework/testsuite.go:50
    should provision storage with snapshot data source [Feature:VolumeSnapshotDataSource]
    test/e2e/storage/testsuites/provisioning.go:208
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] provisioning should provision storage with snapshot data source [Feature:VolumeSnapshotDataSource]","total":35,"completed":5,"skipped":363,"failed":0}

SSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Ephemeral Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  
  should check snapshot fields, check restore correctly works, check deletion (ephemeral)
  test/e2e/storage/testsuites/snapshottable.go:177
... skipping 10 lines ...
[It] should check snapshot fields, check restore correctly works, check deletion (ephemeral)
  test/e2e/storage/testsuites/snapshottable.go:177
Jan 20 19:10:12.572: INFO: Creating resource for dynamic PV
Jan 20 19:10:12.572: INFO: Using claimSize:5Gi, test suite supported size:{ 1Mi}, driver(test.csi.azure.com) supported size:{ 1Mi} 
STEP: creating a StorageClass snapshotting-1777-e2e-sckk5r4
STEP: [init] starting a pod to use the claim
Jan 20 19:10:12.795: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-kmpbl" in namespace "snapshotting-1777" to be "Succeeded or Failed"
Jan 20 19:10:12.903: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 108.697016ms
Jan 20 19:10:15.013: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218495652s
Jan 20 19:10:17.125: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.330012765s
Jan 20 19:10:19.235: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.440385822s
Jan 20 19:10:21.351: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.556278891s
Jan 20 19:10:23.464: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 10.669070107s
Jan 20 19:10:25.574: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 12.779058919s
Jan 20 19:10:27.685: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 14.890665317s
Jan 20 19:10:29.795: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 17.000636014s
Jan 20 19:10:31.905: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Pending", Reason="", readiness=false. Elapsed: 19.11030768s
Jan 20 19:10:34.015: INFO: Pod "pvc-snapshottable-tester-kmpbl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 21.220375797s
STEP: Saw pod success
Jan 20 19:10:34.015: INFO: Pod "pvc-snapshottable-tester-kmpbl" satisfied condition "Succeeded or Failed"
STEP: [init] checking the claim
STEP: creating a SnapshotClass
STEP: creating a dynamic VolumeSnapshot
Jan 20 19:10:34.464: INFO: Waiting up to 5m0s for VolumeSnapshot snapshot-kwrj4 to become ready
Jan 20 19:10:34.573: INFO: VolumeSnapshot snapshot-kwrj4 found but is not ready.
Jan 20 19:10:36.684: INFO: VolumeSnapshot snapshot-kwrj4 found but is not ready.
... skipping 40 lines ...
Jan 20 19:11:32.653: INFO: volumesnapshotcontents snapcontent-b5e24343-e3fa-472f-96af-f92958812e72 has been found and is not deleted
Jan 20 19:11:33.763: INFO: volumesnapshotcontents snapcontent-b5e24343-e3fa-472f-96af-f92958812e72 has been found and is not deleted
Jan 20 19:11:34.874: INFO: volumesnapshotcontents snapcontent-b5e24343-e3fa-472f-96af-f92958812e72 has been found and is not deleted
Jan 20 19:11:35.984: INFO: volumesnapshotcontents snapcontent-b5e24343-e3fa-472f-96af-f92958812e72 has been found and is not deleted
Jan 20 19:11:37.094: INFO: volumesnapshotcontents snapcontent-b5e24343-e3fa-472f-96af-f92958812e72 has been found and is not deleted
Jan 20 19:11:38.203: INFO: volumesnapshotcontents snapcontent-b5e24343-e3fa-472f-96af-f92958812e72 has been found and is not deleted
Jan 20 19:11:39.204: INFO: WaitUntil failed after reaching the timeout 30s
[AfterEach] volume snapshot controller
  test/e2e/storage/testsuites/snapshottable.go:172
Jan 20 19:11:39.354: INFO: Pod restored-pvc-tester-978hh has the following logs: 
Jan 20 19:11:39.354: INFO: Deleting pod "restored-pvc-tester-978hh" in namespace "snapshotting-1777"
Jan 20 19:11:39.464: INFO: Wait up to 5m0s for pod "restored-pvc-tester-978hh" to be fully deleted
Jan 20 19:12:11.682: INFO: deleting snapshot "snapshotting-1777"/"snapshot-kwrj4"
... skipping 26 lines ...
    test/e2e/storage/testsuites/snapshottable.go:113
      
      test/e2e/storage/testsuites/snapshottable.go:176
        should check snapshot fields, check restore correctly works, check deletion (ephemeral)
        test/e2e/storage/testsuites/snapshottable.go:177
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Ephemeral Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  should check snapshot fields, check restore correctly works, check deletion (ephemeral)","total":29,"completed":5,"skipped":421,"failed":0}

SSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (xfs)][Slow] volumes
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:12:19.562: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 196 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:298
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should concurrently access the single volume from pods on the same node","total":24,"completed":5,"skipped":895,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] 
  should concurrently access the single volume from pods on the same node
  test/e2e/storage/testsuites/multivolume.go:298
... skipping 153 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:298
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] should concurrently access the single volume from pods on the same node","total":29,"completed":6,"skipped":647,"failed":0}

SSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:12:29.828: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 59 lines ...
Jan 20 19:09:42.615: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.coml5n8t] to have phase Bound
Jan 20 19:09:42.724: INFO: PersistentVolumeClaim test.csi.azure.coml5n8t found but phase is Pending instead of Bound.
Jan 20 19:09:44.837: INFO: PersistentVolumeClaim test.csi.azure.coml5n8t found but phase is Pending instead of Bound.
Jan 20 19:09:46.948: INFO: PersistentVolumeClaim test.csi.azure.coml5n8t found and phase=Bound (4.333022382s)
STEP: [init] starting a pod to use the claim
STEP: [init] check pod success
Jan 20 19:09:47.391: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-sm5gx" in namespace "snapshotting-7802" to be "Succeeded or Failed"
Jan 20 19:09:47.499: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 108.310129ms
Jan 20 19:09:49.609: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217422906s
Jan 20 19:09:51.719: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.327575347s
Jan 20 19:09:53.828: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.436916504s
Jan 20 19:09:55.937: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.546370028s
Jan 20 19:09:58.047: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.655688614s
... skipping 3 lines ...
Jan 20 19:10:06.486: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 19.095266134s
Jan 20 19:10:08.600: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 21.208394542s
Jan 20 19:10:10.709: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 23.318291898s
Jan 20 19:10:12.824: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Pending", Reason="", readiness=false. Elapsed: 25.433052072s
Jan 20 19:10:14.934: INFO: Pod "pvc-snapshottable-tester-sm5gx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 27.543244428s
STEP: Saw pod success
Jan 20 19:10:14.934: INFO: Pod "pvc-snapshottable-tester-sm5gx" satisfied condition "Succeeded or Failed"
STEP: [init] checking the claim
Jan 20 19:10:15.043: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.coml5n8t] to have phase Bound
Jan 20 19:10:15.151: INFO: PersistentVolumeClaim test.csi.azure.coml5n8t found and phase=Bound (108.100888ms)
STEP: [init] checking the PV
STEP: [init] deleting the pod
Jan 20 19:10:15.481: INFO: Pod pvc-snapshottable-tester-sm5gx has the following logs: 
... skipping 33 lines ...
Jan 20 19:10:23.918: INFO: WaitUntil finished successfully after 112.425559ms
STEP: getting the snapshot and snapshot content
STEP: checking the snapshot
STEP: checking the SnapshotContent
STEP: Modifying source data test
STEP: modifying the data in the source PVC
Jan 20 19:10:24.465: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-data-tester-m4vph" in namespace "snapshotting-7802" to be "Succeeded or Failed"
Jan 20 19:10:24.581: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 115.819322ms
Jan 20 19:10:26.690: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 2.224852458s
Jan 20 19:10:28.802: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 4.33756014s
Jan 20 19:10:30.911: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 6.446659591s
Jan 20 19:10:33.021: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 8.556291726s
Jan 20 19:10:35.131: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 10.665866235s
... skipping 29 lines ...
Jan 20 19:11:38.469: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 1m14.004708995s
Jan 20 19:11:40.583: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Pending", Reason="", readiness=false. Elapsed: 1m16.117747259s
Jan 20 19:11:42.693: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Running", Reason="", readiness=true. Elapsed: 1m18.228226521s
Jan 20 19:11:44.804: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Running", Reason="", readiness=false. Elapsed: 1m20.339489825s
Jan 20 19:11:46.915: INFO: Pod "pvc-snapshottable-data-tester-m4vph": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m22.450675619s
STEP: Saw pod success
Jan 20 19:11:46.916: INFO: Pod "pvc-snapshottable-data-tester-m4vph" satisfied condition "Succeeded or Failed"
Jan 20 19:11:47.172: INFO: Pod pvc-snapshottable-data-tester-m4vph has the following logs: 
Jan 20 19:11:47.173: INFO: Deleting pod "pvc-snapshottable-data-tester-m4vph" in namespace "snapshotting-7802"
Jan 20 19:11:47.288: INFO: Wait up to 5m0s for pod "pvc-snapshottable-data-tester-m4vph" to be fully deleted
STEP: creating a pvc from the snapshot
STEP: starting a pod to use the snapshot
Jan 20 19:12:17.846: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uyqkadau.westeurope.cloudapp.azure.com --kubeconfig=/root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json --namespace=snapshotting-7802 exec restored-pvc-tester-w5bvs --namespace=snapshotting-7802 -- cat /mnt/test/data'
... skipping 47 lines ...
    test/e2e/storage/testsuites/snapshottable.go:113
      
      test/e2e/storage/testsuites/snapshottable.go:176
        should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)
        test/e2e/storage/testsuites/snapshottable.go:278
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Pre-provisioned Snapshot (delete policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)","total":34,"completed":4,"skipped":135,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (xfs)][Slow] multiVolume [Slow] 
  should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
  test/e2e/storage/testsuites/multivolume.go:378
... skipping 84 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (xfs)][Slow] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
    test/e2e/storage/testsuites/multivolume.go:378
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (xfs)][Slow] multiVolume [Slow] should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]","total":37,"completed":5,"skipped":465,"failed":0}

SSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] 
  should access to two volumes with the same volume mode and retain data across pod recreation on different node
  test/e2e/storage/testsuites/multivolume.go:168
... skipping 195 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should access to two volumes with the same volume mode and retain data across pod recreation on different node
    test/e2e/storage/testsuites/multivolume.go:168
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should access to two volumes with the same volume mode and retain data across pod recreation on different node","total":42,"completed":5,"skipped":193,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:14:43.151: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 3 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:242

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 128 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
    test/e2e/storage/testsuites/multivolume.go:378
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]","total":24,"completed":6,"skipped":921,"failed":0}

SSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] 
  should access to two volumes with different volume mode and retain data across pod recreation on different node
  test/e2e/storage/testsuites/multivolume.go:248
... skipping 189 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should access to two volumes with different volume mode and retain data across pod recreation on different node
    test/e2e/storage/testsuites/multivolume.go:248
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should access to two volumes with different volume mode and retain data across pod recreation on different node","total":35,"completed":6,"skipped":367,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:15:12.119: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 3 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:280

    Distro debian doesn't support ntfs -- skipping

    test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 309 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] provisioning
  test/e2e/storage/framework/testsuite.go:50
    should provision storage with pvc data source in parallel [Slow]
    test/e2e/storage/testsuites/provisioning.go:459
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] provisioning should provision storage with pvc data source in parallel [Slow]","total":29,"completed":7,"skipped":671,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:15:16.009: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 103 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (xfs)][Slow] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single read-only volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:423
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (xfs)][Slow] multiVolume [Slow] should concurrently access the single read-only volume from pods on the same node","total":34,"completed":5,"skipped":196,"failed":0}

S
------------------------------
[BeforeEach] [Testpattern: Ephemeral Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Ephemeral Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
... skipping 87 lines ...
Jan 20 19:14:44.194: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comm2hgx] to have phase Bound
Jan 20 19:14:44.303: INFO: PersistentVolumeClaim test.csi.azure.comm2hgx found but phase is Pending instead of Bound.
Jan 20 19:14:46.412: INFO: PersistentVolumeClaim test.csi.azure.comm2hgx found but phase is Pending instead of Bound.
Jan 20 19:14:48.521: INFO: PersistentVolumeClaim test.csi.azure.comm2hgx found and phase=Bound (4.326717843s)
STEP: Creating pod exec-volume-test-dynamicpv-7mmg
STEP: Creating a pod to test exec-volume-test
Jan 20 19:14:48.850: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-7mmg" in namespace "volume-6087" to be "Succeeded or Failed"
Jan 20 19:14:48.958: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 108.797366ms
Jan 20 19:14:51.069: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219161299s
Jan 20 19:14:53.179: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 4.329327353s
Jan 20 19:14:55.290: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 6.440260895s
Jan 20 19:14:57.399: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 8.549692585s
Jan 20 19:14:59.509: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 10.658969856s
... skipping 4 lines ...
Jan 20 19:15:10.059: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 21.209090812s
Jan 20 19:15:12.173: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 23.323783405s
Jan 20 19:15:14.283: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 25.433243157s
Jan 20 19:15:16.393: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Pending", Reason="", readiness=false. Elapsed: 27.543375558s
Jan 20 19:15:18.503: INFO: Pod "exec-volume-test-dynamicpv-7mmg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 29.653219828s
STEP: Saw pod success
Jan 20 19:15:18.503: INFO: Pod "exec-volume-test-dynamicpv-7mmg" satisfied condition "Succeeded or Failed"
Jan 20 19:15:18.616: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000000 pod exec-volume-test-dynamicpv-7mmg container exec-container-dynamicpv-7mmg: <nil>
STEP: delete the pod
Jan 20 19:15:18.846: INFO: Waiting for pod exec-volume-test-dynamicpv-7mmg to disappear
Jan 20 19:15:18.954: INFO: Pod exec-volume-test-dynamicpv-7mmg no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-7mmg
Jan 20 19:15:18.954: INFO: Deleting pod "exec-volume-test-dynamicpv-7mmg" in namespace "volume-6087"
... skipping 27 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (xfs)][Slow] volumes
  test/e2e/storage/framework/testsuite.go:50
    should allow exec of files on the volume
    test/e2e/storage/testsuites/volumes.go:198
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (xfs)][Slow] volumes should allow exec of files on the volume","total":42,"completed":6,"skipped":271,"failed":0}
[BeforeEach] [Testpattern: Pre-provisioned PV (filesystem volmode)] volumeMode
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:16:31.379: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
[AfterEach] [Testpattern: Pre-provisioned PV (filesystem volmode)] volumeMode
  test/e2e/framework/framework.go:188


S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Pre-provisioned PV (filesystem volmode)] volumeMode
  test/e2e/storage/framework/testsuite.go:50
    should fail to use a volume in a pod with mismatched mode [Slow] [BeforeEach]
    test/e2e/storage/testsuites/volumemode.go:299

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 75 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  test/e2e/storage/framework/testsuite.go:50
    should support two pods which have the same volume definition
    test/e2e/storage/testsuites/ephemeral.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral should support two pods which have the same volume definition","total":29,"completed":6,"skipped":445,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral 
  should create read-only inline ephemeral volume
  test/e2e/storage/testsuites/ephemeral.go:175
... skipping 52 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  test/e2e/storage/framework/testsuite.go:50
    should create read-only inline ephemeral volume
    test/e2e/storage/testsuites/ephemeral.go:175
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral should create read-only inline ephemeral volume","total":37,"completed":6,"skipped":486,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] 
  should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
  test/e2e/storage/testsuites/multivolume.go:378
... skipping 82 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]
    test/e2e/storage/testsuites/multivolume.go:378
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] should concurrently access the volume and its clone from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]","total":24,"completed":7,"skipped":938,"failed":0}

SSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext3)] volumes 
  should allow exec of files on the volume
  test/e2e/storage/testsuites/volumes.go:198
... skipping 17 lines ...
Jan 20 19:15:40.107: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.combhcpl] to have phase Bound
Jan 20 19:15:40.216: INFO: PersistentVolumeClaim test.csi.azure.combhcpl found but phase is Pending instead of Bound.
Jan 20 19:15:42.326: INFO: PersistentVolumeClaim test.csi.azure.combhcpl found but phase is Pending instead of Bound.
Jan 20 19:15:44.444: INFO: PersistentVolumeClaim test.csi.azure.combhcpl found and phase=Bound (4.337161091s)
STEP: Creating pod exec-volume-test-dynamicpv-l84s
STEP: Creating a pod to test exec-volume-test
Jan 20 19:15:44.776: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-l84s" in namespace "volume-4026" to be "Succeeded or Failed"
Jan 20 19:15:44.886: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 110.205201ms
Jan 20 19:15:46.997: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 2.221346664s
Jan 20 19:15:49.107: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 4.331681321s
Jan 20 19:15:51.221: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 6.445210994s
Jan 20 19:15:53.331: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 8.555393752s
Jan 20 19:15:55.444: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 10.668178922s
... skipping 23 lines ...
Jan 20 19:16:46.123: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 1m1.346772926s
Jan 20 19:16:48.233: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 1m3.456838129s
Jan 20 19:16:50.344: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 1m5.567925473s
Jan 20 19:16:52.454: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Pending", Reason="", readiness=false. Elapsed: 1m7.678308085s
Jan 20 19:16:54.565: INFO: Pod "exec-volume-test-dynamicpv-l84s": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m9.788814233s
STEP: Saw pod success
Jan 20 19:16:54.565: INFO: Pod "exec-volume-test-dynamicpv-l84s" satisfied condition "Succeeded or Failed"
Jan 20 19:16:54.675: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000002 pod exec-volume-test-dynamicpv-l84s container exec-container-dynamicpv-l84s: <nil>
STEP: delete the pod
Jan 20 19:16:54.928: INFO: Waiting for pod exec-volume-test-dynamicpv-l84s to disappear
Jan 20 19:16:55.037: INFO: Pod exec-volume-test-dynamicpv-l84s no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-l84s
Jan 20 19:16:55.037: INFO: Deleting pod "exec-volume-test-dynamicpv-l84s" in namespace "volume-4026"
... skipping 21 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext3)] volumes
  test/e2e/storage/framework/testsuite.go:50
    should allow exec of files on the volume
    test/e2e/storage/testsuites/volumes.go:198
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext3)] volumes should allow exec of files on the volume","total":34,"completed":6,"skipped":458,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should verify container cannot write to subpath readonly volumes [Slow]
  test/e2e/storage/testsuites/subpath.go:425
... skipping 16 lines ...
Jan 20 19:16:49.480: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Jan 20 19:16:49.591: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comwclxk] to have phase Bound
Jan 20 19:16:49.699: INFO: PersistentVolumeClaim test.csi.azure.comwclxk found but phase is Pending instead of Bound.
Jan 20 19:16:51.811: INFO: PersistentVolumeClaim test.csi.azure.comwclxk found but phase is Pending instead of Bound.
Jan 20 19:16:53.920: INFO: PersistentVolumeClaim test.csi.azure.comwclxk found and phase=Bound (4.329546164s)
STEP: Creating pod to format volume volume-prep-provisioning-9849
Jan 20 19:16:54.253: INFO: Waiting up to 5m0s for pod "volume-prep-provisioning-9849" in namespace "provisioning-9849" to be "Succeeded or Failed"
Jan 20 19:16:54.361: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 108.73391ms
Jan 20 19:16:56.471: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 2.217893193s
Jan 20 19:16:58.580: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 4.327060355s
Jan 20 19:17:00.690: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 6.437310809s
Jan 20 19:17:02.800: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 8.547396267s
Jan 20 19:17:04.910: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 10.657752098s
... skipping 7 lines ...
Jan 20 19:17:21.794: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 27.540902776s
Jan 20 19:17:23.903: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 29.650797843s
Jan 20 19:17:26.013: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 31.760102386s
Jan 20 19:17:28.122: INFO: Pod "volume-prep-provisioning-9849": Phase="Pending", Reason="", readiness=false. Elapsed: 33.869488125s
Jan 20 19:17:30.232: INFO: Pod "volume-prep-provisioning-9849": Phase="Succeeded", Reason="", readiness=false. Elapsed: 35.979398047s
STEP: Saw pod success
Jan 20 19:17:30.232: INFO: Pod "volume-prep-provisioning-9849" satisfied condition "Succeeded or Failed"
Jan 20 19:17:30.232: INFO: Deleting pod "volume-prep-provisioning-9849" in namespace "provisioning-9849"
Jan 20 19:17:30.348: INFO: Wait up to 5m0s for pod "volume-prep-provisioning-9849" to be fully deleted
STEP: Creating pod pod-subpath-test-dynamicpv-gw7r
STEP: Checking for subpath error in container status
Jan 20 19:17:40.793: INFO: Deleting pod "pod-subpath-test-dynamicpv-gw7r" in namespace "provisioning-9849"
Jan 20 19:17:40.906: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-gw7r" to be fully deleted
STEP: Deleting pod
Jan 20 19:17:43.125: INFO: Deleting pod "pod-subpath-test-dynamicpv-gw7r" in namespace "provisioning-9849"
STEP: Deleting pvc
Jan 20 19:17:43.234: INFO: Deleting PersistentVolumeClaim "test.csi.azure.comwclxk"
... skipping 19 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should verify container cannot write to subpath readonly volumes [Slow]
    test/e2e/storage/testsuites/subpath.go:425
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should verify container cannot write to subpath readonly volumes [Slow]","total":37,"completed":7,"skipped":562,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Ephemeral Snapshot (delete policy)] snapshottable[Feature:VolumeSnapshotDataSource]
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Ephemeral Snapshot (delete policy)] snapshottable[Feature:VolumeSnapshotDataSource]
... skipping 247 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should access to two volumes with the same volume mode and retain data across pod recreation on the same node
    test/e2e/storage/testsuites/multivolume.go:138
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] should access to two volumes with the same volume mode and retain data across pod recreation on the same node","total":42,"completed":7,"skipped":296,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:18:37.667: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 128 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (block volmode) (late-binding)] ephemeral
  test/e2e/storage/framework/testsuite.go:50
    should support multiple inline ephemeral volumes
    test/e2e/storage/testsuites/ephemeral.go:254
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (block volmode) (late-binding)] ephemeral should support multiple inline ephemeral volumes","total":29,"completed":7,"skipped":509,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  
  should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)
  test/e2e/storage/testsuites/snapshottable.go:278
... skipping 17 lines ...
Jan 20 19:15:13.146: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comrhmtb] to have phase Bound
Jan 20 19:15:13.254: INFO: PersistentVolumeClaim test.csi.azure.comrhmtb found but phase is Pending instead of Bound.
Jan 20 19:15:15.366: INFO: PersistentVolumeClaim test.csi.azure.comrhmtb found but phase is Pending instead of Bound.
Jan 20 19:15:17.479: INFO: PersistentVolumeClaim test.csi.azure.comrhmtb found and phase=Bound (4.333371115s)
STEP: [init] starting a pod to use the claim
STEP: [init] check pod success
Jan 20 19:15:17.932: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-k9jht" in namespace "snapshotting-9622" to be "Succeeded or Failed"
Jan 20 19:15:18.041: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 108.796492ms
Jan 20 19:15:20.150: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218372597s
Jan 20 19:15:22.260: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 4.327764913s
Jan 20 19:15:24.369: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 6.437197912s
Jan 20 19:15:26.480: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 8.548432641s
Jan 20 19:15:28.590: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 10.657976445s
Jan 20 19:15:30.700: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 12.767694658s
Jan 20 19:15:32.810: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Pending", Reason="", readiness=false. Elapsed: 14.878369309s
Jan 20 19:15:34.920: INFO: Pod "pvc-snapshottable-tester-k9jht": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.988559415s
STEP: Saw pod success
Jan 20 19:15:34.920: INFO: Pod "pvc-snapshottable-tester-k9jht" satisfied condition "Succeeded or Failed"
STEP: [init] checking the claim
Jan 20 19:15:35.029: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comrhmtb] to have phase Bound
Jan 20 19:15:35.138: INFO: PersistentVolumeClaim test.csi.azure.comrhmtb found and phase=Bound (108.740483ms)
STEP: [init] checking the PV
STEP: [init] deleting the pod
Jan 20 19:15:35.470: INFO: Pod pvc-snapshottable-tester-k9jht has the following logs: 
... skipping 16 lines ...
Jan 20 19:15:49.548: INFO: received snapshotStatus map[boundVolumeSnapshotContentName:snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 creationTime:2023-01-20T19:15:45Z readyToUse:true restoreSize:5Gi]
Jan 20 19:15:49.548: INFO: snapshotContentName snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2
STEP: checking the snapshot
STEP: checking the SnapshotContent
STEP: Modifying source data test
STEP: modifying the data in the source PVC
Jan 20 19:15:49.988: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-data-tester-fd668" in namespace "snapshotting-9622" to be "Succeeded or Failed"
Jan 20 19:15:50.098: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 109.512154ms
Jan 20 19:15:52.208: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 2.22014166s
Jan 20 19:15:54.318: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 4.330379438s
Jan 20 19:15:56.428: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 6.439929566s
Jan 20 19:15:58.538: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 8.550264489s
Jan 20 19:16:00.650: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 10.662233348s
... skipping 26 lines ...
Jan 20 19:16:57.643: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 1m7.654511188s
Jan 20 19:16:59.752: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 1m9.76420923s
Jan 20 19:17:01.866: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 1m11.877768517s
Jan 20 19:17:03.975: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Pending", Reason="", readiness=false. Elapsed: 1m13.98731839s
Jan 20 19:17:06.086: INFO: Pod "pvc-snapshottable-data-tester-fd668": Phase="Succeeded", Reason="", readiness=false. Elapsed: 1m16.097409247s
STEP: Saw pod success
Jan 20 19:17:06.086: INFO: Pod "pvc-snapshottable-data-tester-fd668" satisfied condition "Succeeded or Failed"
Jan 20 19:17:06.336: INFO: Pod pvc-snapshottable-data-tester-fd668 has the following logs: 
Jan 20 19:17:06.336: INFO: Deleting pod "pvc-snapshottable-data-tester-fd668" in namespace "snapshotting-9622"
Jan 20 19:17:06.467: INFO: Wait up to 5m0s for pod "pvc-snapshottable-data-tester-fd668" to be fully deleted
STEP: creating a pvc from the snapshot
STEP: starting a pod to use the snapshot
Jan 20 19:18:05.025: INFO: Running '/usr/local/bin/kubectl --server=https://kubetest-uyqkadau.westeurope.cloudapp.azure.com --kubeconfig=/root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json --namespace=snapshotting-9622 exec restored-pvc-tester-tzwxt --namespace=snapshotting-9622 -- cat /mnt/test/data'
... skipping 32 lines ...
Jan 20 19:18:30.279: INFO: volumesnapshotcontents snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 has been found and is not deleted
Jan 20 19:18:31.389: INFO: volumesnapshotcontents snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 has been found and is not deleted
Jan 20 19:18:32.499: INFO: volumesnapshotcontents snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 has been found and is not deleted
Jan 20 19:18:33.611: INFO: volumesnapshotcontents snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 has been found and is not deleted
Jan 20 19:18:34.721: INFO: volumesnapshotcontents snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 has been found and is not deleted
Jan 20 19:18:35.831: INFO: volumesnapshotcontents snapcontent-c491b713-9bee-4ced-84f9-67e733328fd2 has been found and is not deleted
Jan 20 19:18:36.831: INFO: WaitUntil failed after reaching the timeout 30s
[AfterEach] volume snapshot controller
  test/e2e/storage/testsuites/snapshottable.go:172
Jan 20 19:18:36.965: INFO: Pod restored-pvc-tester-tzwxt has the following logs: 
Jan 20 19:18:36.965: INFO: Deleting pod "restored-pvc-tester-tzwxt" in namespace "snapshotting-9622"
Jan 20 19:18:37.074: INFO: Wait up to 5m0s for pod "restored-pvc-tester-tzwxt" to be fully deleted
Jan 20 19:18:39.292: INFO: deleting claim "snapshotting-9622"/"pvc-g9nbf"
... skipping 31 lines ...
    test/e2e/storage/testsuites/snapshottable.go:113
      
      test/e2e/storage/testsuites/snapshottable.go:176
        should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)
        test/e2e/storage/testsuites/snapshottable.go:278
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  should check snapshot fields, check restore correctly works after modifying source data, check deletion (persistent)","total":35,"completed":7,"skipped":434,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (delayed binding)] topology
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (delayed binding)] topology
  test/e2e/framework/framework.go:187
STEP: Creating a kubernetes client
Jan 20 19:18:57.524: INFO: >>> kubeConfig: /root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json
STEP: Building a namespace api object, basename topology
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
[It] should fail to schedule a pod which has topologies that conflict with AllowedTopologies
  test/e2e/storage/testsuites/topology.go:194
Jan 20 19:18:58.282: INFO: Driver didn't provide topology keys -- skipping
[AfterEach] [Testpattern: Dynamic PV (delayed binding)] topology
  test/e2e/framework/framework.go:188
Jan 20 19:18:58.282: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "topology-6300" for this suite.


S [SKIPPING] [1.002 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (delayed binding)] topology
  test/e2e/storage/framework/testsuite.go:50
    should fail to schedule a pod which has topologies that conflict with AllowedTopologies [Measurement]
    test/e2e/storage/testsuites/topology.go:194

    Driver didn't provide topology keys -- skipping

    test/e2e/storage/testsuites/topology.go:126
------------------------------
... skipping 172 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should be able to unmount after the subpath directory is deleted [LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:447
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should be able to unmount after the subpath directory is deleted [LinuxOnly]","total":42,"completed":8,"skipped":424,"failed":0}

SSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:19:47.000: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 131 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral
  test/e2e/storage/framework/testsuite.go:50
    should support two pods which have the same volume definition
    test/e2e/storage/testsuites/ephemeral.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral should support two pods which have the same volume definition","total":29,"completed":8,"skipped":853,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] volumes
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:20:03.873: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 133 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] volumes
  test/e2e/storage/framework/testsuite.go:50
    should store data
    test/e2e/storage/testsuites/volumes.go:161
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes should store data","total":34,"completed":7,"skipped":496,"failed":0}

SSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:20:04.156: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 109 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should concurrently access the single read-only volume from pods on the same node
    test/e2e/storage/testsuites/multivolume.go:423
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] should concurrently access the single read-only volume from pods on the same node","total":37,"completed":8,"skipped":651,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:20:11.242: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 131 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] volumes
  test/e2e/storage/framework/testsuite.go:50
    should store data
    test/e2e/storage/testsuites/volumes.go:161
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] volumes should store data","total":29,"completed":8,"skipped":552,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:20:27.086: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 3 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:280

    Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 160 lines ...
Jan 20 19:20:28.103: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvlkrd] to have phase Bound
Jan 20 19:20:28.215: INFO: PersistentVolumeClaim test.csi.azure.comvlkrd found but phase is Pending instead of Bound.
Jan 20 19:20:30.324: INFO: PersistentVolumeClaim test.csi.azure.comvlkrd found but phase is Pending instead of Bound.
Jan 20 19:20:32.453: INFO: PersistentVolumeClaim test.csi.azure.comvlkrd found and phase=Bound (4.349642158s)
STEP: Creating pod pod-subpath-test-dynamicpv-ppsx
STEP: Creating a pod to test subpath
Jan 20 19:20:32.783: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-ppsx" in namespace "provisioning-158" to be "Succeeded or Failed"
Jan 20 19:20:32.892: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 109.03173ms
Jan 20 19:20:35.002: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.218826342s
Jan 20 19:20:37.112: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.328945929s
Jan 20 19:20:39.223: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.439690314s
Jan 20 19:20:41.334: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.550953938s
Jan 20 19:20:43.448: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.664420827s
... skipping 4 lines ...
Jan 20 19:20:53.999: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 21.21535184s
Jan 20 19:20:56.108: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 23.324974892s
Jan 20 19:20:58.219: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 25.435787009s
Jan 20 19:21:00.330: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Pending", Reason="", readiness=false. Elapsed: 27.546466163s
Jan 20 19:21:02.439: INFO: Pod "pod-subpath-test-dynamicpv-ppsx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 29.655743825s
STEP: Saw pod success
Jan 20 19:21:02.439: INFO: Pod "pod-subpath-test-dynamicpv-ppsx" satisfied condition "Succeeded or Failed"
Jan 20 19:21:02.548: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000002 pod pod-subpath-test-dynamicpv-ppsx container test-container-subpath-dynamicpv-ppsx: <nil>
STEP: delete the pod
Jan 20 19:21:02.803: INFO: Waiting for pod pod-subpath-test-dynamicpv-ppsx to disappear
Jan 20 19:21:02.912: INFO: Pod pod-subpath-test-dynamicpv-ppsx no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-ppsx
Jan 20 19:21:02.912: INFO: Deleting pod "pod-subpath-test-dynamicpv-ppsx" in namespace "provisioning-158"
... skipping 23 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should support readOnly directory specified in the volumeMount
    test/e2e/storage/testsuites/subpath.go:367
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support readOnly directory specified in the volumeMount","total":29,"completed":9,"skipped":615,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow]
... skipping 129 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] volumes
  test/e2e/storage/framework/testsuite.go:50
    should store data
    test/e2e/storage/testsuites/volumes.go:161
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] volumes should store data","total":35,"completed":8,"skipped":639,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if subpath file is outside the volume [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:258

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/framework/framework.go:187
STEP: Creating a kubernetes client
Jan 20 19:20:11.255: INFO: >>> kubeConfig: /root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json
STEP: Building a namespace api object, basename provisioning
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
[It] should fail if subpath file is outside the volume [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:258
Jan 20 19:20:12.015: INFO: Creating resource for dynamic PV
Jan 20 19:20:12.015: INFO: Using claimSize:5Gi, test suite supported size:{ 1Mi}, driver(test.csi.azure.com) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-6111-e2e-sc9b9rp
STEP: creating a claim
Jan 20 19:20:12.130: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Jan 20 19:20:12.242: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com2sfvs] to have phase Bound
Jan 20 19:20:12.351: INFO: PersistentVolumeClaim test.csi.azure.com2sfvs found but phase is Pending instead of Bound.
Jan 20 19:20:14.460: INFO: PersistentVolumeClaim test.csi.azure.com2sfvs found but phase is Pending instead of Bound.
Jan 20 19:20:16.576: INFO: PersistentVolumeClaim test.csi.azure.com2sfvs found and phase=Bound (4.333700292s)
STEP: Creating pod pod-subpath-test-dynamicpv-fsjj
STEP: Checking for subpath error in container status
Jan 20 19:20:55.123: INFO: Deleting pod "pod-subpath-test-dynamicpv-fsjj" in namespace "provisioning-6111"
Jan 20 19:20:55.233: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-fsjj" to be fully deleted
STEP: Deleting pod
Jan 20 19:20:57.452: INFO: Deleting pod "pod-subpath-test-dynamicpv-fsjj" in namespace "provisioning-6111"
STEP: Deleting pvc
Jan 20 19:20:57.560: INFO: Deleting PersistentVolumeClaim "test.csi.azure.com2sfvs"
... skipping 22 lines ...

• [SLOW TEST:118.630 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath file is outside the volume [Slow][LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:258
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should fail if subpath file is outside the volume [Slow][LinuxOnly]","total":37,"completed":9,"skipped":710,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:22:09.916: INFO: Distro debian doesn't support ntfs -- skipping
... skipping 43 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath file is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:258

    Distro debian doesn't support ntfs -- skipping

    test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 36 lines ...
[It] should check snapshot fields, check restore correctly works, check deletion (ephemeral)
  test/e2e/storage/testsuites/snapshottable.go:177
Jan 20 19:20:04.933: INFO: Creating resource for dynamic PV
Jan 20 19:20:04.933: INFO: Using claimSize:5Gi, test suite supported size:{ 1Mi}, driver(test.csi.azure.com) supported size:{ 1Mi} 
STEP: creating a StorageClass snapshotting-939-e2e-sczzzmb
STEP: [init] starting a pod to use the claim
Jan 20 19:20:05.159: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-78vx9" in namespace "snapshotting-939" to be "Succeeded or Failed"
Jan 20 19:20:05.269: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 109.819154ms
Jan 20 19:20:07.380: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.220604962s
Jan 20 19:20:09.490: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.330625933s
Jan 20 19:20:11.601: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.441867561s
Jan 20 19:20:13.711: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.552028469s
Jan 20 19:20:15.821: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 10.661949884s
Jan 20 19:20:17.933: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 12.77315611s
Jan 20 19:20:20.043: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 14.88391685s
Jan 20 19:20:22.154: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 16.994997901s
Jan 20 19:20:24.265: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Pending", Reason="", readiness=false. Elapsed: 19.105296398s
Jan 20 19:20:26.375: INFO: Pod "pvc-snapshottable-tester-78vx9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 21.21540638s
STEP: Saw pod success
Jan 20 19:20:26.375: INFO: Pod "pvc-snapshottable-tester-78vx9" satisfied condition "Succeeded or Failed"
STEP: [init] checking the claim
STEP: creating a SnapshotClass
STEP: creating a dynamic VolumeSnapshot
Jan 20 19:20:26.822: INFO: Waiting up to 5m0s for VolumeSnapshot snapshot-jslkd to become ready
Jan 20 19:20:26.931: INFO: VolumeSnapshot snapshot-jslkd found but is not ready.
Jan 20 19:20:29.042: INFO: VolumeSnapshot snapshot-jslkd found but is not ready.
... skipping 49 lines ...
    test/e2e/storage/testsuites/snapshottable.go:113
      
      test/e2e/storage/testsuites/snapshottable.go:176
        should check snapshot fields, check restore correctly works, check deletion (ephemeral)
        test/e2e/storage/testsuites/snapshottable.go:177
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Ephemeral Snapshot (delete policy)] snapshottable[Feature:VolumeSnapshotDataSource] volume snapshot controller  should check snapshot fields, check restore correctly works, check deletion (ephemeral)","total":34,"completed":8,"skipped":523,"failed":0}

SSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] volumes
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:22:28.626: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 16 lines ...
SSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy 
  (Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with different fsgroup applied to the volume contents
  test/e2e/storage/testsuites/fsgroupchangepolicy.go:216

{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (xfs)][Slow] multiVolume [Slow] should concurrently access the volume and restored snapshot from pods on the same node [LinuxOnly][Feature:VolumeSnapshotDataSource][Feature:VolumeSourceXFS]","total":24,"completed":8,"skipped":959,"failed":0}
[BeforeEach] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/framework/framework.go:187
STEP: Creating a kubernetes client
Jan 20 19:21:25.253: INFO: >>> kubeConfig: /root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json
... skipping 106 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/storage/framework/testsuite.go:50
    (Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with different fsgroup applied to the volume contents
    test/e2e/storage/testsuites/fsgroupchangepolicy.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed via chgrp in first pod, new pod with different fsgroup applied to the volume contents","total":24,"completed":9,"skipped":959,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
Jan 20 19:22:50.755: INFO: Running AfterSuite actions on all nodes
Jan 20 19:22:50.755: INFO: Running Cleanup Action: k8s.io/kubernetes/test/e2e/storage.glob..func19.2
Jan 20 19:22:50.755: INFO: Running Cleanup Action: k8s.io/kubernetes/test/e2e/storage.glob..func9.2
... skipping 27 lines ...
Jan 20 19:21:46.837: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comlcnkl] to have phase Bound
Jan 20 19:21:46.946: INFO: PersistentVolumeClaim test.csi.azure.comlcnkl found but phase is Pending instead of Bound.
Jan 20 19:21:49.056: INFO: PersistentVolumeClaim test.csi.azure.comlcnkl found but phase is Pending instead of Bound.
Jan 20 19:21:51.166: INFO: PersistentVolumeClaim test.csi.azure.comlcnkl found and phase=Bound (4.328829555s)
STEP: Creating pod exec-volume-test-dynamicpv-vpdf
STEP: Creating a pod to test exec-volume-test
Jan 20 19:21:51.504: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-vpdf" in namespace "volume-8769" to be "Succeeded or Failed"
Jan 20 19:21:51.614: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 109.579281ms
Jan 20 19:21:53.723: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 2.219148721s
Jan 20 19:21:55.833: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 4.329240598s
Jan 20 19:21:57.948: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 6.444366461s
Jan 20 19:22:00.058: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 8.553673808s
Jan 20 19:22:02.167: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 10.663276794s
Jan 20 19:22:04.277: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 12.773246596s
Jan 20 19:22:06.387: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 14.882739409s
Jan 20 19:22:08.497: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 16.993201753s
Jan 20 19:22:10.606: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 19.102339147s
Jan 20 19:22:12.717: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Pending", Reason="", readiness=false. Elapsed: 21.213073136s
Jan 20 19:22:14.829: INFO: Pod "exec-volume-test-dynamicpv-vpdf": Phase="Succeeded", Reason="", readiness=false. Elapsed: 23.324541286s
STEP: Saw pod success
Jan 20 19:22:14.829: INFO: Pod "exec-volume-test-dynamicpv-vpdf" satisfied condition "Succeeded or Failed"
Jan 20 19:22:14.938: INFO: Trying to get logs from node k8s-agentpool1-28728053-vmss000000 pod exec-volume-test-dynamicpv-vpdf container exec-container-dynamicpv-vpdf: <nil>
STEP: delete the pod
Jan 20 19:22:15.179: INFO: Waiting for pod exec-volume-test-dynamicpv-vpdf to disappear
Jan 20 19:22:15.288: INFO: Pod exec-volume-test-dynamicpv-vpdf no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-vpdf
Jan 20 19:22:15.288: INFO: Deleting pod "exec-volume-test-dynamicpv-vpdf" in namespace "volume-8769"
... skipping 21 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (ext4)] volumes
  test/e2e/storage/framework/testsuite.go:50
    should allow exec of files on the volume
    test/e2e/storage/testsuites/volumes.go:198
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (ext4)] volumes should allow exec of files on the volume","total":29,"completed":10,"skipped":690,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] 
  should access to two volumes with the same volume mode and retain data across pod recreation on different node
  test/e2e/storage/testsuites/multivolume.go:168
... skipping 188 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:50
    should access to two volumes with the same volume mode and retain data across pod recreation on different node
    test/e2e/storage/testsuites/multivolume.go:168
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] should access to two volumes with the same volume mode and retain data across pod recreation on different node","total":42,"completed":9,"skipped":456,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (filesystem volmode)] multiVolume [Slow]
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:22:57.512: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 118 lines ...
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy
  test/e2e/storage/framework/testsuite.go:50
    (Always)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents
    test/e2e/storage/testsuites/fsgroupchangepolicy.go:216
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (Always)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents","total":35,"completed":9,"skipped":681,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:23:45.279: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 45 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Pre-provisioned PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath file is outside the volume [Slow][LinuxOnly] [BeforeEach]
    test/e2e/storage/testsuites/subpath.go:258

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
... skipping 5 lines ...
  test/e2e/framework/framework.go:187
STEP: Creating a kubernetes client
Jan 20 19:23:45.419: INFO: >>> kubeConfig: /root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json
STEP: Building a namespace api object, basename topology
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
[It] should fail to schedule a pod which has topologies that conflict with AllowedTopologies
  test/e2e/storage/testsuites/topology.go:194
Jan 20 19:23:46.178: INFO: Driver didn't provide topology keys -- skipping
[AfterEach] [Testpattern: Dynamic PV (immediate binding)] topology
  test/e2e/framework/framework.go:188
Jan 20 19:23:46.179: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "topology-1337" for this suite.


S [SKIPPING] [0.980 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (immediate binding)] topology
  test/e2e/storage/framework/testsuite.go:50
    should fail to schedule a pod which has topologies that conflict with AllowedTopologies [Measurement]
    test/e2e/storage/testsuites/topology.go:194

    Driver didn't provide topology keys -- skipping

    test/e2e/storage/testsuites/topology.go:126
------------------------------
... skipping 18 lines ...

    test/e2e/storage/external/external.go:262
------------------------------
SSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if subpath directory is outside the volume [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:242

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/framework/framework.go:187
STEP: Creating a kubernetes client
Jan 20 19:22:28.641: INFO: >>> kubeConfig: /root/tmp3809346268/kubeconfig/kubeconfig.westeurope.json
STEP: Building a namespace api object, basename provisioning
STEP: Waiting for a default service account to be provisioned in namespace
STEP: Waiting for kube-root-ca.crt to be provisioned in namespace
[It] should fail if subpath directory is outside the volume [Slow][LinuxOnly]
  test/e2e/storage/testsuites/subpath.go:242
Jan 20 19:22:29.415: INFO: Creating resource for dynamic PV
Jan 20 19:22:29.415: INFO: Using claimSize:5Gi, test suite supported size:{ 1Mi}, driver(test.csi.azure.com) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-6138-e2e-sckqzxq
STEP: creating a claim
Jan 20 19:22:29.525: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Jan 20 19:22:29.638: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comf5gvs] to have phase Bound
Jan 20 19:22:29.747: INFO: PersistentVolumeClaim test.csi.azure.comf5gvs found but phase is Pending instead of Bound.
Jan 20 19:22:31.856: INFO: PersistentVolumeClaim test.csi.azure.comf5gvs found but phase is Pending instead of Bound.
Jan 20 19:22:33.974: INFO: PersistentVolumeClaim test.csi.azure.comf5gvs found and phase=Bound (4.335710376s)
STEP: Creating pod pod-subpath-test-dynamicpv-dksq
STEP: Checking for subpath error in container status
Jan 20 19:23:52.536: INFO: Deleting pod "pod-subpath-test-dynamicpv-dksq" in namespace "provisioning-6138"
Jan 20 19:23:52.651: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-dksq" to be fully deleted
STEP: Deleting pod
Jan 20 19:23:54.880: INFO: Deleting pod "pod-subpath-test-dynamicpv-dksq" in namespace "provisioning-6138"
STEP: Deleting pvc
Jan 20 19:23:54.989: INFO: Deleting PersistentVolumeClaim "test.csi.azure.comf5gvs"
... skipping 16 lines ...

• [SLOW TEST:128.008 seconds]
External Storage [Driver: test.csi.azure.com]
test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:50
    should fail if subpath directory is outside the volume [Slow][LinuxOnly]
    test/e2e/storage/testsuites/subpath.go:242
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should fail if subpath directory is outside the volume [Slow][LinuxOnly]","total":34,"completed":9,"skipped":553,"failed":0}
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/storage/framework/testsuite.go:51
Jan 20 19:24:36.655: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
[AfterEach] [Testpattern: Inline-volume (default fs)] subPath
  test/e2e/framework/framework.go:188

... skipping 28 lines ...
    test/e2e/storage/testsuites/multivolume.go:298

    Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping

    test/e2e/storage/external/external.go:262
------------------------------
SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS{"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-20T19:24:41Z"}
++ early_exit_handler
++ '[' -n 167 ']'
++ kill -TERM 167
++ cleanup_dind
++ [[ true == \t\r\u\e ]]
++ echo 'Cleaning up after docker'
... skipping 4 lines ...