This job view page is being replaced by Spyglass soon. Check out the new job view.
PRandyzhangx: feat: enable fsGroup for nfs
ResultFAILURE
Tests 1 failed / 11 succeeded
Started2021-09-14 11:26
Elapsed32m9s
Revisionc3f3a26c5dc4274e681aee7fc89d3f4952061280
Refs 759
job-versionv1.23.0-alpha.1.467+95391adbc00e11
kubetest-version
revisionv1.23.0-alpha.1.467+95391adbc00e11

Test Failures


kubetest Test 22m0s

error during make e2e-test: exit status 2
				from junit_runner.xml

Filter through log files | View test history on testgrid


Show 11 Passed Tests

Error lines from build-log.txt

... skipping 222 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11248  100 11248    0     0  34931      0 --:--:-- --:--:-- --:--:-- 34931
Downloading https://get.helm.sh/helm-v3.6.3-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/azurefile-csi:e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 || make container-all push-manifest
Error response from daemon: manifest for k8sprow.azurecr.io/azurefile-csi:e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 not found: manifest unknown: manifest tagged by "e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96" is not found
make[2]: Entering directory '/home/prow/go/src/sigs.k8s.io/azurefile-csi-driver'
CGO_ENABLED=0 GOOS=windows go build -a -ldflags "-X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.driverVersion=e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=80a180586d0bbf0275aa10e601cb4ab5bc334c96 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2021-09-14T11:29:18Z -s -w -extldflags '-static'" -mod vendor -o _output/amd64/azurefileplugin.exe ./pkg/azurefileplugin
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 1710 lines ...
                    type: string
                type: object
                oneOf:
                - required: ["persistentVolumeClaimName"]
                - required: ["volumeSnapshotContentName"]
              volumeSnapshotClassName:
                description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.'
                type: string
            required:
            - source
            type: object
          status:
            description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.
... skipping 2 lines ...
                description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.'
                type: string
              creationTime:
                description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown.
                format: date-time
                type: string
              error:
                description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared.
                properties:
                  message:
                    description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.'
                    type: string
                  time:
                    description: time is the timestamp when the error was encountered.
                    format: date-time
                    type: string
                type: object
              readyToUse:
                description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown.
                type: boolean
              restoreSize:
                type: string
                description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown.
                pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$
                x-kubernetes-int-or-string: true
            type: object
        required:
        - spec
        type: object
... skipping 55 lines ...
                    type: string
                  volumeSnapshotContentName:
                    description: volumeSnapshotContentName specifies the name of a pre-existing VolumeSnapshotContent object representing an existing volume snapshot. This field should be set if the snapshot already exists and only needs a representation in Kubernetes. This field is immutable.
                    type: string
                type: object
              volumeSnapshotClassName:
                description: 'VolumeSnapshotClassName is the name of the VolumeSnapshotClass requested by the VolumeSnapshot. VolumeSnapshotClassName may be left nil to indicate that the default SnapshotClass should be used. A given cluster may have multiple default Volume SnapshotClasses: one default per CSI Driver. If a VolumeSnapshot does not specify a SnapshotClass, VolumeSnapshotSource will be checked to figure out what the associated CSI Driver is, and the default VolumeSnapshotClass associated with that CSI Driver will be used. If more than one VolumeSnapshotClass exist for a given CSI Driver and more than one have been marked as default, CreateSnapshot will fail and generate an event. Empty string is not allowed for this field.'
                type: string
            required:
            - source
            type: object
          status:
            description: status represents the current information of a snapshot. Consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.
... skipping 2 lines ...
                description: 'boundVolumeSnapshotContentName is the name of the VolumeSnapshotContent object to which this VolumeSnapshot object intends to bind to. If not specified, it indicates that the VolumeSnapshot object has not been successfully bound to a VolumeSnapshotContent object yet. NOTE: To avoid possible security issues, consumers must verify binding between VolumeSnapshot and VolumeSnapshotContent objects is successful (by validating that both VolumeSnapshot and VolumeSnapshotContent point at each other) before using this object.'
                type: string
              creationTime:
                description: creationTime is the timestamp when the point-in-time snapshot is taken by the underlying storage system. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "creation_time" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "creation_time" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. If not specified, it may indicate that the creation time of the snapshot is unknown.
                format: date-time
                type: string
              error:
                description: error is the last observed error during snapshot creation, if any. This field could be helpful to upper level controllers(i.e., application controller) to decide whether they should continue on waiting for the snapshot to be created based on the type of error reported. The snapshot controller will keep retrying when an error occurrs during the snapshot creation. Upon success, this error field will be cleared.
                properties:
                  message:
                    description: 'message is a string detailing the encountered error during snapshot creation if specified. NOTE: message may be logged, and it should not contain sensitive information.'
                    type: string
                  time:
                    description: time is the timestamp when the error was encountered.
                    format: date-time
                    type: string
                type: object
              readyToUse:
                description: readyToUse indicates if the snapshot is ready to be used to restore a volume. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "ready_to_use" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "ready_to_use" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it, otherwise, this field will be set to "True". If not specified, it means the readiness of a snapshot is unknown.
                type: boolean
              restoreSize:
                type: string
                description: restoreSize represents the minimum size of volume required to create a volume from this snapshot. In dynamic snapshot creation case, this field will be filled in by the snapshot controller with the "size_bytes" value returned from CSI "CreateSnapshot" gRPC call. For a pre-existing snapshot, this field will be filled with the "size_bytes" value returned from the CSI "ListSnapshots" gRPC call if the driver supports it. When restoring a volume from this snapshot, the size of the volume MUST NOT be smaller than the restoreSize if it is specified, otherwise the restoration will fail. If not specified, it indicates that the size is unknown.
                pattern: ^(\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))(([KMGTPE]i)|[numkMGTPE]|([eE](\+|-)?(([0-9]+(\.[0-9]*)?)|(\.[0-9]+))))?$
                x-kubernetes-int-or-string: true
            type: object
        required:
        - spec
        type: object
... skipping 239 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 99 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 829 lines ...
        - name: csi-resizer
          image: "mcr.microsoft.com/oss/kubernetes-csi/csi-resizer:v1.3.0"
          args:
            - "-csi-address=$(ADDRESS)"
            - "-v=2"
            - "-leader-election"
            - '-handle-volume-inuse-error=false'
          env:
            - name: ADDRESS
              value: /csi/csi.sock
          imagePullPolicy: IfNotPresent
          volumeMounts:
            - name: socket-dir
... skipping 743 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should store data
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:159
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes should store data","total":11,"completed":1,"skipped":429,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)(allowExpansion)] volume-expand 
  Verify if offline PVC expansion works
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_expand.go:174
... skipping 79 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)(allowExpansion)] volume-expand
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    Verify if offline PVC expansion works
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_expand.go:174
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)(allowExpansion)] volume-expand Verify if offline PVC expansion works","total":10,"completed":1,"skipped":155,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Pre-provisioned Snapshot (retain policy)] snapshottable[Feature:VolumeSnapshotDataSource]
... skipping 10 lines ...
STEP: creating a claim
Sep 14 11:39:14.045: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:39:14.090: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comxqr7j] to have phase Bound
Sep 14 11:39:14.122: INFO: PersistentVolumeClaim test.csi.azure.comxqr7j found but phase is Pending instead of Bound.
Sep 14 11:39:16.155: INFO: PersistentVolumeClaim test.csi.azure.comxqr7j found and phase=Bound (2.064279272s)
STEP: [init] starting a pod to use the claim
Sep 14 11:39:16.251: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-pw9rp" in namespace "snapshotting-221" to be "Succeeded or Failed"
Sep 14 11:39:16.282: INFO: Pod "pvc-snapshottable-tester-pw9rp": Phase="Pending", Reason="", readiness=false. Elapsed: 31.550269ms
Sep 14 11:39:18.315: INFO: Pod "pvc-snapshottable-tester-pw9rp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064078324s
Sep 14 11:39:20.389: INFO: Pod "pvc-snapshottable-tester-pw9rp": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.137957686s
STEP: Saw pod success
Sep 14 11:39:20.389: INFO: Pod "pvc-snapshottable-tester-pw9rp" satisfied condition "Succeeded or Failed"
Sep 14 11:39:20.456: INFO: Pod pvc-snapshottable-tester-pw9rp has the following logs: 
Sep 14 11:39:20.456: INFO: Deleting pod "pvc-snapshottable-tester-pw9rp" in namespace "snapshotting-221"
Sep 14 11:39:20.491: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-pw9rp" to be fully deleted
Sep 14 11:39:20.523: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comxqr7j] to have phase Bound
Sep 14 11:39:20.554: INFO: PersistentVolumeClaim test.csi.azure.comxqr7j found and phase=Bound (31.469876ms)
STEP: [init] checking the claim
... skipping 109 lines ...
Sep 14 11:38:48.168: INFO: PersistentVolumeClaim test.csi.azure.comphtpl found but phase is Pending instead of Bound.
Sep 14 11:38:50.219: INFO: PersistentVolumeClaim test.csi.azure.comphtpl found but phase is Pending instead of Bound.
Sep 14 11:38:52.253: INFO: PersistentVolumeClaim test.csi.azure.comphtpl found but phase is Pending instead of Bound.
Sep 14 11:38:54.284: INFO: PersistentVolumeClaim test.csi.azure.comphtpl found and phase=Bound (54.939651289s)
STEP: Expanding non-expandable pvc
Sep 14 11:38:54.348: INFO: currentPvcSize {{5368709120 0} {<nil>} 5Gi BinarySI}, newSize {{6442450944 0} {<nil>}  BinarySI}
Sep 14 11:38:54.412: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:38:56.479: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:38:58.480: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:00.475: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:02.478: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:04.477: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:06.477: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:08.478: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:10.476: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:12.483: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:14.476: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:16.477: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:18.475: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:20.476: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:22.479: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:24.476: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 14 11:39:24.540: INFO: Error updating pvc test.csi.azure.comphtpl: persistentvolumeclaims "test.csi.azure.comphtpl" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
STEP: Deleting pvc
Sep 14 11:39:24.540: INFO: Deleting PersistentVolumeClaim "test.csi.azure.comphtpl"
Sep 14 11:39:24.573: INFO: Waiting up to 5m0s for PersistentVolume pvc-8873b8d5-9e41-4495-8533-062e10290e73 to get deleted
Sep 14 11:39:24.605: INFO: PersistentVolume pvc-8873b8d5-9e41-4495-8533-062e10290e73 found and phase=Released (31.517961ms)
Sep 14 11:39:29.637: INFO: PersistentVolume pvc-8873b8d5-9e41-4495-8533-062e10290e73 was removed
STEP: Deleting sc
... skipping 8 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] volume-expand
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should not allow expansion of pvcs without AllowVolumeExpansion property
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_expand.go:157
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volume-expand should not allow expansion of pvcs without AllowVolumeExpansion property","total":18,"completed":1,"skipped":215,"failed":0}

SSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:39:29.781: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 126 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)(allowExpansion)] volume-expand
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should resize volume when PVC is edited while pod is using it
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_expand.go:246
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)(allowExpansion)] volume-expand should resize volume when PVC is edited while pod is using it","total":10,"completed":2,"skipped":201,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:39:30.765: INFO: Driver "test.csi.azure.com" does not provide raw block - skipping
... skipping 102 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should create read-only inline ephemeral volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:149
------------------------------
{"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":19,"completed":1,"skipped":120,"failed":0}

SSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:39:32.538: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 60 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should create read/write inline ephemeral volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:166
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral should create read/write inline ephemeral volume","total":9,"completed":1,"skipped":701,"failed":0}

S
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support readOnly file specified in the volumeMount [LinuxOnly]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:380
... skipping 15 lines ...
Sep 14 11:39:33.405: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:39:33.439: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comqmlwp] to have phase Bound
Sep 14 11:39:33.471: INFO: PersistentVolumeClaim test.csi.azure.comqmlwp found but phase is Pending instead of Bound.
Sep 14 11:39:35.503: INFO: PersistentVolumeClaim test.csi.azure.comqmlwp found and phase=Bound (2.063217801s)
STEP: Creating pod pod-subpath-test-dynamicpv-brln
STEP: Creating a pod to test subpath
Sep 14 11:39:35.601: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-brln" in namespace "provisioning-4752" to be "Succeeded or Failed"
Sep 14 11:39:35.636: INFO: Pod "pod-subpath-test-dynamicpv-brln": Phase="Pending", Reason="", readiness=false. Elapsed: 35.175868ms
Sep 14 11:39:37.670: INFO: Pod "pod-subpath-test-dynamicpv-brln": Phase="Pending", Reason="", readiness=false. Elapsed: 2.068844599s
Sep 14 11:39:39.703: INFO: Pod "pod-subpath-test-dynamicpv-brln": Phase="Pending", Reason="", readiness=false. Elapsed: 4.102123279s
Sep 14 11:39:41.736: INFO: Pod "pod-subpath-test-dynamicpv-brln": Phase="Pending", Reason="", readiness=false. Elapsed: 6.134897123s
Sep 14 11:39:43.769: INFO: Pod "pod-subpath-test-dynamicpv-brln": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8.167592073s
STEP: Saw pod success
Sep 14 11:39:43.769: INFO: Pod "pod-subpath-test-dynamicpv-brln" satisfied condition "Succeeded or Failed"
Sep 14 11:39:43.801: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000001 pod pod-subpath-test-dynamicpv-brln container test-container-subpath-dynamicpv-brln: <nil>
STEP: delete the pod
Sep 14 11:39:43.874: INFO: Waiting for pod pod-subpath-test-dynamicpv-brln to disappear
Sep 14 11:39:43.906: INFO: Pod pod-subpath-test-dynamicpv-brln no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-brln
Sep 14 11:39:43.906: INFO: Deleting pod "pod-subpath-test-dynamicpv-brln" in namespace "provisioning-4752"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support readOnly file specified in the volumeMount [LinuxOnly]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:380
------------------------------
{"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":9,"completed":2,"skipped":702,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:39:49.218: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 84 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should be able to unmount after the subpath directory is deleted [LinuxOnly]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:445
------------------------------
{"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":9,"completed":3,"skipped":855,"failed":0}

SSSSSSSS
------------------------------
[BeforeEach] [Testpattern: CSI Ephemeral-volume (default fs)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:40:05.880: INFO: Driver "test.csi.azure.com" does not support volume type "CSIInlineVolume" - skipping
... skipping 67 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should create read/write inline ephemeral volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:166
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral should create read/write inline ephemeral volume","total":11,"completed":2,"skipped":651,"failed":0}
[BeforeEach] [Testpattern: CSI Ephemeral-volume (default fs)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:40:07.323: INFO: Driver "test.csi.azure.com" does not support volume type "CSIInlineVolume" - skipping
[AfterEach] [Testpattern: CSI Ephemeral-volume (default fs)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:186

... skipping 160 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support multiple inline ephemeral volumes
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:221
------------------------------
{"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":19,"completed":2,"skipped":151,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:40:13.632: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 66 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support two pods which share the same volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:183
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral should support two pods which share the same volume","total":10,"completed":3,"skipped":606,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support existing single file [LinuxOnly]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:219
... skipping 15 lines ...
Sep 14 11:40:47.328: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:40:47.369: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.coml475c] to have phase Bound
Sep 14 11:40:47.400: INFO: PersistentVolumeClaim test.csi.azure.coml475c found but phase is Pending instead of Bound.
Sep 14 11:40:49.434: INFO: PersistentVolumeClaim test.csi.azure.coml475c found and phase=Bound (2.064959458s)
STEP: Creating pod pod-subpath-test-dynamicpv-pp7r
STEP: Creating a pod to test subpath
Sep 14 11:40:49.530: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-pp7r" in namespace "provisioning-2660" to be "Succeeded or Failed"
Sep 14 11:40:49.562: INFO: Pod "pod-subpath-test-dynamicpv-pp7r": Phase="Pending", Reason="", readiness=false. Elapsed: 31.700921ms
Sep 14 11:40:51.594: INFO: Pod "pod-subpath-test-dynamicpv-pp7r": Phase="Pending", Reason="", readiness=false. Elapsed: 2.063977636s
Sep 14 11:40:53.627: INFO: Pod "pod-subpath-test-dynamicpv-pp7r": Phase="Pending", Reason="", readiness=false. Elapsed: 4.096841843s
Sep 14 11:40:55.660: INFO: Pod "pod-subpath-test-dynamicpv-pp7r": Phase="Pending", Reason="", readiness=false. Elapsed: 6.130054829s
Sep 14 11:40:57.694: INFO: Pod "pod-subpath-test-dynamicpv-pp7r": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8.16380112s
STEP: Saw pod success
Sep 14 11:40:57.694: INFO: Pod "pod-subpath-test-dynamicpv-pp7r" satisfied condition "Succeeded or Failed"
Sep 14 11:40:57.725: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000000 pod pod-subpath-test-dynamicpv-pp7r container test-container-subpath-dynamicpv-pp7r: <nil>
STEP: delete the pod
Sep 14 11:40:57.799: INFO: Waiting for pod pod-subpath-test-dynamicpv-pp7r to disappear
Sep 14 11:40:57.830: INFO: Pod pod-subpath-test-dynamicpv-pp7r no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-pp7r
Sep 14 11:40:57.830: INFO: Deleting pod "pod-subpath-test-dynamicpv-pp7r" in namespace "provisioning-2660"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support existing single file [LinuxOnly]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:219
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support existing single file [LinuxOnly]","total":10,"completed":4,"skipped":674,"failed":0}

SSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes 
  should allow exec of files on the volume
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:196
... skipping 15 lines ...
Sep 14 11:41:03.322: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:41:03.356: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com7674t] to have phase Bound
Sep 14 11:41:03.388: INFO: PersistentVolumeClaim test.csi.azure.com7674t found but phase is Pending instead of Bound.
Sep 14 11:41:05.421: INFO: PersistentVolumeClaim test.csi.azure.com7674t found and phase=Bound (2.064331852s)
STEP: Creating pod exec-volume-test-dynamicpv-vnxl
STEP: Creating a pod to test exec-volume-test
Sep 14 11:41:05.519: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-vnxl" in namespace "volume-8773" to be "Succeeded or Failed"
Sep 14 11:41:05.551: INFO: Pod "exec-volume-test-dynamicpv-vnxl": Phase="Pending", Reason="", readiness=false. Elapsed: 31.75971ms
Sep 14 11:41:07.584: INFO: Pod "exec-volume-test-dynamicpv-vnxl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064805865s
Sep 14 11:41:09.616: INFO: Pod "exec-volume-test-dynamicpv-vnxl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.097001628s
STEP: Saw pod success
Sep 14 11:41:09.616: INFO: Pod "exec-volume-test-dynamicpv-vnxl" satisfied condition "Succeeded or Failed"
Sep 14 11:41:09.648: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000001 pod exec-volume-test-dynamicpv-vnxl container exec-container-dynamicpv-vnxl: <nil>
STEP: delete the pod
Sep 14 11:41:09.723: INFO: Waiting for pod exec-volume-test-dynamicpv-vnxl to disappear
Sep 14 11:41:09.754: INFO: Pod exec-volume-test-dynamicpv-vnxl no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-vnxl
Sep 14 11:41:09.755: INFO: Deleting pod "exec-volume-test-dynamicpv-vnxl" in namespace "volume-8773"
... skipping 14 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should allow exec of files on the volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:196
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes should allow exec of files on the volume","total":10,"completed":5,"skipped":680,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral 
  should support two pods which share the same volume
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:183
... skipping 45 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support two pods which share the same volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:183
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral should support two pods which share the same volume","total":19,"completed":3,"skipped":378,"failed":0}
[BeforeEach] [Testpattern: Pre-provisioned PV (ntfs)][Feature:Windows] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:41:27.784: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
[AfterEach] [Testpattern: Pre-provisioned PV (ntfs)][Feature:Windows] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:186

... skipping 42 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (immediate binding)] topology
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should fail to schedule a pod which has topologies that conflict with AllowedTopologies [BeforeEach]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/topology.go:192

    Driver "test.csi.azure.com" does not support topology - skipping

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/topology.go:92
------------------------------
... skipping 241 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should create read-only inline ephemeral volume
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:149
------------------------------
{"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":10,"completed":6,"skipped":705,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (block volmode)(allowExpansion)] volume-expand
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:41:56.552: INFO: Driver "test.csi.azure.com" does not support block volume mode - skipping
... skipping 82 lines ...
Sep 14 11:38:56.480: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/file1] Namespace:fsgroupchangepolicy-6470 PodName:pod-ec61789e-85ee-4227-9aca-81b304bf84d2 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:38:56.480: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:38:56.918: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/file1] Namespace:fsgroupchangepolicy-6470 PodName:pod-ec61789e-85ee-4227-9aca-81b304bf84d2 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:38:56.918: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:38:57.284: INFO: pod fsgroupchangepolicy-6470/pod-ec61789e-85ee-4227-9aca-81b304bf84d2 exec for cmd ls -l /mnt/volume1/file1, stdout: -rw-r--r--    1 root     root             0 Sep 14 11:38 /mnt/volume1/file1, stderr: 
Sep 14 11:38:57.284: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 14 11:38 /mnt/volume1/file1], expected gid: 1000
Sep 14 11:38:57.285: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc003193b80, 0x709327d, 0x12, 0xc000c81848, 0x4, 0xc000581c00)
... skipping 71 lines ...
Sep 14 11:43:34.209: INFO: PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 found and phase=Bound (4m36.891719225s)
Sep 14 11:43:39.242: INFO: PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 found and phase=Bound (4m41.92480841s)
Sep 14 11:43:44.275: INFO: PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 found and phase=Bound (4m46.957227136s)
Sep 14 11:43:49.309: INFO: PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 found and phase=Bound (4m51.99113209s)
Sep 14 11:43:54.341: INFO: PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 found and phase=Bound (4m57.023368448s)
STEP: Deleting sc
Sep 14 11:43:59.375: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 not deleted by dynamic provisioner: PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-4c6f4be7-aa2e-4464-b36d-e28124c3ba85 still exists within 5m0s",
... skipping 6 lines ...

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/testsuites.(*fsGroupChangePolicyTestSuite).DefineTests.func2()
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:132 +0xf0
panic(0x6bf5d00, 0xc0031cab00)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc003292410, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc0025ff400, 0x499)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:63 +0xa5
panic(0x6323060, 0x77ced70)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc003292410, 0x4c, 0xc0028fac38, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:67 +0x1b5
k8s.io/kubernetes/test/e2e/framework.Fail(0xc0031a3780, 0x37, 0xc0041f84e0, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/log.go:62 +0x1ea
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).match(0xc0028fadc0, 0x7904368, 0xc00234fe10, 0x1, 0x0, 0x0, 0x0, 0xc00234fe10)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:79 +0x216
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc0028fadc0, 0x7904368, 0xc00234fe10, 0x0, 0x0, 0x0, 0xa09f580)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework.ExpectEqual(0x6323060, 0xc00234fdf0, 0x6323060, 0xc00234fe00, 0x0, 0x0, 0x0)
... skipping 140 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED 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":14,"completed":0,"skipped":108,"failed":1,"failures":["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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (default fs)] capacity
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:44:00.623: INFO: Driver test.csi.azure.com doesn't publish storage capacity -- skipping
... skipping 287 lines ...
Sep 14 11:38:57.152: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/file1] Namespace:fsgroupchangepolicy-5292 PodName:pod-eae601c6-7fcc-438d-8746-37d66e298942 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:38:57.152: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:38:57.950: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/file1] Namespace:fsgroupchangepolicy-5292 PodName:pod-eae601c6-7fcc-438d-8746-37d66e298942 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:38:57.950: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:38:58.451: INFO: pod fsgroupchangepolicy-5292/pod-eae601c6-7fcc-438d-8746-37d66e298942 exec for cmd ls -l /mnt/volume1/file1, stdout: -rw-r--r--    1 root     root             0 Sep 14 11:38 /mnt/volume1/file1, stderr: 
Sep 14 11:38:58.451: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 14 11:38 /mnt/volume1/file1], expected gid: 1000
Sep 14 11:38:58.451: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc003e71760, 0x709327d, 0x12, 0xc004189178, 0x4, 0xc003c47000)
... skipping 71 lines ...
Sep 14 11:43:35.343: INFO: PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 found and phase=Bound (4m36.857388089s)
Sep 14 11:43:40.375: INFO: PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 found and phase=Bound (4m41.88959941s)
Sep 14 11:43:45.408: INFO: PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 found and phase=Bound (4m46.922944569s)
Sep 14 11:43:50.442: INFO: PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 found and phase=Bound (4m51.956802587s)
Sep 14 11:43:55.476: INFO: PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 found and phase=Bound (4m56.990126816s)
STEP: Deleting sc
Sep 14 11:44:00.509: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 not deleted by dynamic provisioner: PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-4462f3ce-6a1c-422b-85ac-e511e8d60235 still exists within 5m0s",
... skipping 6 lines ...

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/testsuites.(*fsGroupChangePolicyTestSuite).DefineTests.func2()
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:132 +0xf0
panic(0x6bf5d00, 0xc003473300)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc0020b3810, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc0025f3400, 0x499)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:63 +0xa5
panic(0x6323060, 0x77ced70)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc0020b3810, 0x4c, 0xc00417ac38, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:67 +0x1b5
k8s.io/kubernetes/test/e2e/framework.Fail(0xc0025b12c0, 0x37, 0xc0025aab50, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/log.go:62 +0x1ea
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).match(0xc00417adc0, 0x7904368, 0xc0025aeb40, 0x1, 0x0, 0x0, 0x0, 0xc0025aeb40)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:79 +0x216
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc00417adc0, 0x7904368, 0xc0025aeb40, 0x0, 0x0, 0x0, 0xa09f580)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework.ExpectEqual(0x6323060, 0xc0025aeb20, 0x6323060, 0xc0025aeb30, 0x0, 0x0, 0x0)
... skipping 140 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED 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 in first pod, new pod with different fsgroup applied to the volume contents","total":28,"completed":0,"skipped":356,"failed":1,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents"]}

SSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support non-existent path
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:194
... skipping 15 lines ...
Sep 14 11:44:01.756: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:44:01.789: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvtsdz] to have phase Bound
Sep 14 11:44:01.821: INFO: PersistentVolumeClaim test.csi.azure.comvtsdz found but phase is Pending instead of Bound.
Sep 14 11:44:03.854: INFO: PersistentVolumeClaim test.csi.azure.comvtsdz found and phase=Bound (2.064809923s)
STEP: Creating pod pod-subpath-test-dynamicpv-bkvq
STEP: Creating a pod to test subpath
Sep 14 11:44:03.955: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-bkvq" in namespace "provisioning-7325" to be "Succeeded or Failed"
Sep 14 11:44:03.987: INFO: Pod "pod-subpath-test-dynamicpv-bkvq": Phase="Pending", Reason="", readiness=false. Elapsed: 31.954793ms
Sep 14 11:44:06.019: INFO: Pod "pod-subpath-test-dynamicpv-bkvq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064420449s
Sep 14 11:44:08.051: INFO: Pod "pod-subpath-test-dynamicpv-bkvq": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.096814148s
STEP: Saw pod success
Sep 14 11:44:08.052: INFO: Pod "pod-subpath-test-dynamicpv-bkvq" satisfied condition "Succeeded or Failed"
Sep 14 11:44:08.083: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000000 pod pod-subpath-test-dynamicpv-bkvq container test-container-volume-dynamicpv-bkvq: <nil>
STEP: delete the pod
Sep 14 11:44:08.160: INFO: Waiting for pod pod-subpath-test-dynamicpv-bkvq to disappear
Sep 14 11:44:08.191: INFO: Pod pod-subpath-test-dynamicpv-bkvq no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-bkvq
Sep 14 11:44:08.191: INFO: Deleting pod "pod-subpath-test-dynamicpv-bkvq" in namespace "provisioning-7325"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support non-existent path
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:194
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support non-existent path","total":28,"completed":1,"skipped":375,"failed":1,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents"]}

SSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support existing directories when readOnly specified in the volumeSource
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:395
... skipping 15 lines ...
Sep 14 11:44:01.718: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:44:01.751: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.coms9d2x] to have phase Bound
Sep 14 11:44:01.782: INFO: PersistentVolumeClaim test.csi.azure.coms9d2x found but phase is Pending instead of Bound.
Sep 14 11:44:03.815: INFO: PersistentVolumeClaim test.csi.azure.coms9d2x found and phase=Bound (2.063642055s)
STEP: Creating pod pod-subpath-test-dynamicpv-gm55
STEP: Creating a pod to test subpath
Sep 14 11:44:03.912: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-gm55" in namespace "provisioning-2664" to be "Succeeded or Failed"
Sep 14 11:44:03.944: INFO: Pod "pod-subpath-test-dynamicpv-gm55": Phase="Pending", Reason="", readiness=false. Elapsed: 31.675678ms
Sep 14 11:44:05.983: INFO: Pod "pod-subpath-test-dynamicpv-gm55": Phase="Pending", Reason="", readiness=false. Elapsed: 2.071264728s
Sep 14 11:44:08.016: INFO: Pod "pod-subpath-test-dynamicpv-gm55": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.104126171s
STEP: Saw pod success
Sep 14 11:44:08.016: INFO: Pod "pod-subpath-test-dynamicpv-gm55" satisfied condition "Succeeded or Failed"
Sep 14 11:44:08.048: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000001 pod pod-subpath-test-dynamicpv-gm55 container test-container-subpath-dynamicpv-gm55: <nil>
STEP: delete the pod
Sep 14 11:44:08.121: INFO: Waiting for pod pod-subpath-test-dynamicpv-gm55 to disappear
Sep 14 11:44:08.152: INFO: Pod pod-subpath-test-dynamicpv-gm55 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-gm55
Sep 14 11:44:08.152: INFO: Deleting pod "pod-subpath-test-dynamicpv-gm55" in namespace "provisioning-2664"
STEP: Creating pod pod-subpath-test-dynamicpv-gm55
STEP: Creating a pod to test subpath
Sep 14 11:44:08.216: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-gm55" in namespace "provisioning-2664" to be "Succeeded or Failed"
Sep 14 11:44:08.248: INFO: Pod "pod-subpath-test-dynamicpv-gm55": Phase="Pending", Reason="", readiness=false. Elapsed: 31.627717ms
Sep 14 11:44:10.280: INFO: Pod "pod-subpath-test-dynamicpv-gm55": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.063970207s
STEP: Saw pod success
Sep 14 11:44:10.280: INFO: Pod "pod-subpath-test-dynamicpv-gm55" satisfied condition "Succeeded or Failed"
Sep 14 11:44:10.312: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000001 pod pod-subpath-test-dynamicpv-gm55 container test-container-subpath-dynamicpv-gm55: <nil>
STEP: delete the pod
Sep 14 11:44:10.381: INFO: Waiting for pod pod-subpath-test-dynamicpv-gm55 to disappear
Sep 14 11:44:10.413: INFO: Pod pod-subpath-test-dynamicpv-gm55 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-gm55
Sep 14 11:44:10.413: INFO: Deleting pod "pod-subpath-test-dynamicpv-gm55" in namespace "provisioning-2664"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support existing directories when readOnly specified in the volumeSource
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:395
------------------------------
{"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":14,"completed":1,"skipped":837,"failed":1,"failures":["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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
Sep 14 11:44:15.806: INFO: Running AfterSuite actions on all nodes
Sep 14 11:44:15.806: INFO: Running Cleanup Action: k8s.io/kubernetes/test/e2e/storage.glob..func17.2
Sep 14 11:44:15.806: INFO: Running Cleanup Action: k8s.io/kubernetes/test/e2e/storage.glob..func8.2
... skipping 25 lines ...
Sep 14 11:44:13.702: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:44:13.736: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comffm7t] to have phase Bound
Sep 14 11:44:13.767: INFO: PersistentVolumeClaim test.csi.azure.comffm7t found but phase is Pending instead of Bound.
Sep 14 11:44:15.800: INFO: PersistentVolumeClaim test.csi.azure.comffm7t found and phase=Bound (2.063743345s)
STEP: Creating pod pod-subpath-test-dynamicpv-bzl8
STEP: Creating a pod to test subpath
Sep 14 11:44:15.897: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-bzl8" in namespace "provisioning-9152" to be "Succeeded or Failed"
Sep 14 11:44:15.929: INFO: Pod "pod-subpath-test-dynamicpv-bzl8": Phase="Pending", Reason="", readiness=false. Elapsed: 31.800229ms
Sep 14 11:44:17.962: INFO: Pod "pod-subpath-test-dynamicpv-bzl8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064391713s
Sep 14 11:44:19.995: INFO: Pod "pod-subpath-test-dynamicpv-bzl8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.097896748s
Sep 14 11:44:22.029: INFO: Pod "pod-subpath-test-dynamicpv-bzl8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.131266514s
STEP: Saw pod success
Sep 14 11:44:22.029: INFO: Pod "pod-subpath-test-dynamicpv-bzl8" satisfied condition "Succeeded or Failed"
Sep 14 11:44:22.061: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000001 pod pod-subpath-test-dynamicpv-bzl8 container test-container-subpath-dynamicpv-bzl8: <nil>
STEP: delete the pod
Sep 14 11:44:22.139: INFO: Waiting for pod pod-subpath-test-dynamicpv-bzl8 to disappear
Sep 14 11:44:22.171: INFO: Pod pod-subpath-test-dynamicpv-bzl8 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-bzl8
Sep 14 11:44:22.171: INFO: Deleting pod "pod-subpath-test-dynamicpv-bzl8" in namespace "provisioning-9152"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support readOnly directory specified in the volumeMount
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:365
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support readOnly directory specified in the volumeMount","total":28,"completed":2,"skipped":399,"failed":1,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents"]}

SSSSSSSSSSSSSSSSSSSSS
------------------------------
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 in first pod, new pod with same fsgroup skips ownership changes to the volume contents
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208
... skipping 22 lines ...
Sep 14 11:39:34.409: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/file1] Namespace:fsgroupchangepolicy-8473 PodName:pod-b4506415-f458-4953-8945-3dbe55531f66 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:39:34.409: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:39:34.853: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/file1] Namespace:fsgroupchangepolicy-8473 PodName:pod-b4506415-f458-4953-8945-3dbe55531f66 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:39:34.853: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:39:35.260: INFO: pod fsgroupchangepolicy-8473/pod-b4506415-f458-4953-8945-3dbe55531f66 exec for cmd ls -l /mnt/volume1/file1, stdout: -rw-r--r--    1 root     root             0 Sep 14 11:39 /mnt/volume1/file1, stderr: 
Sep 14 11:39:35.260: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 14 11:39 /mnt/volume1/file1], expected gid: 1000
Sep 14 11:39:35.260: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc001ada580, 0x709327d, 0x12, 0xc0041a8a58, 0x4, 0xc000500800)
... skipping 71 lines ...
Sep 14 11:44:12.152: INFO: PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 found and phase=Bound (4m36.858417949s)
Sep 14 11:44:17.185: INFO: PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 found and phase=Bound (4m41.89130007s)
Sep 14 11:44:22.217: INFO: PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 found and phase=Bound (4m46.923000936s)
Sep 14 11:44:27.250: INFO: PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 found and phase=Bound (4m51.956756794s)
Sep 14 11:44:32.282: INFO: PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 found and phase=Bound (4m56.988561123s)
STEP: Deleting sc
Sep 14 11:44:37.316: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 not deleted by dynamic provisioner: PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-36d26c62-1fd9-4aa8-a338-e87f231304c1 still exists within 5m0s",
... skipping 6 lines ...

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/testsuites.(*fsGroupChangePolicyTestSuite).DefineTests.func2()
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:132 +0xf0
panic(0x6bf5d00, 0xc002df70c0)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc000f22f50, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc002a88500, 0x499)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:63 +0xa5
panic(0x6323060, 0x77ced70)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc000f22f50, 0x4c, 0xc002cb6c38, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:67 +0x1b5
k8s.io/kubernetes/test/e2e/framework.Fail(0xc002dddb00, 0x37, 0xc003503300, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/log.go:62 +0x1ea
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).match(0xc002cb6dc0, 0x7904368, 0xc0038cc300, 0x1, 0x0, 0x0, 0x0, 0xc0038cc300)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:79 +0x216
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc002cb6dc0, 0x7904368, 0xc0038cc300, 0x0, 0x0, 0x0, 0xa09f580)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework.ExpectEqual(0x6323060, 0xc0038cc2e0, 0x6323060, 0xc0038cc2f0, 0x0, 0x0, 0x0)
... skipping 136 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED 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 in first pod, new pod with same fsgroup skips ownership changes to the volume contents","total":18,"completed":1,"skipped":362,"failed":1,"failures":["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 in first pod, new pod with same fsgroup skips ownership changes to the volume contents"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ext4)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:44:38.422: INFO: Driver test.csi.azure.com doesn't support ext4 -- skipping
... skipping 52 lines ...
STEP: creating a claim
Sep 14 11:44:27.736: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:44:27.770: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.combdss4] to have phase Bound
Sep 14 11:44:27.801: INFO: PersistentVolumeClaim test.csi.azure.combdss4 found but phase is Pending instead of Bound.
Sep 14 11:44:29.834: INFO: PersistentVolumeClaim test.csi.azure.combdss4 found and phase=Bound (2.064391255s)
STEP: [init] starting a pod to use the claim
Sep 14 11:44:29.932: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-vxlz5" in namespace "snapshotting-5225" to be "Succeeded or Failed"
Sep 14 11:44:29.964: INFO: Pod "pvc-snapshottable-tester-vxlz5": Phase="Pending", Reason="", readiness=false. Elapsed: 32.015383ms
Sep 14 11:44:32.000: INFO: Pod "pvc-snapshottable-tester-vxlz5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.067768755s
Sep 14 11:44:34.033: INFO: Pod "pvc-snapshottable-tester-vxlz5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.100774439s
STEP: Saw pod success
Sep 14 11:44:34.033: INFO: Pod "pvc-snapshottable-tester-vxlz5" satisfied condition "Succeeded or Failed"
Sep 14 11:44:34.098: INFO: Pod pvc-snapshottable-tester-vxlz5 has the following logs: 
Sep 14 11:44:34.098: INFO: Deleting pod "pvc-snapshottable-tester-vxlz5" in namespace "snapshotting-5225"
Sep 14 11:44:34.137: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-vxlz5" to be fully deleted
Sep 14 11:44:34.168: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.combdss4] to have phase Bound
Sep 14 11:44:34.200: INFO: PersistentVolumeClaim test.csi.azure.combdss4 found and phase=Bound (31.92645ms)
STEP: [init] checking the claim
... skipping 67 lines ...

S [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds]
External Storage [Driver: test.csi.azure.com]
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (delayed binding)] topology
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should fail to schedule a pod which has topologies that conflict with AllowedTopologies [BeforeEach]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/topology.go:192

    Driver "test.csi.azure.com" does not support topology - skipping

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/topology.go:92
------------------------------
... skipping 99 lines ...
STEP: creating a claim
Sep 14 11:44:39.995: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:44:40.030: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comzj7gt] to have phase Bound
Sep 14 11:44:40.061: INFO: PersistentVolumeClaim test.csi.azure.comzj7gt found but phase is Pending instead of Bound.
Sep 14 11:44:42.095: INFO: PersistentVolumeClaim test.csi.azure.comzj7gt found and phase=Bound (2.06485019s)
STEP: [init] starting a pod to use the claim
Sep 14 11:44:42.191: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-d4jct" in namespace "snapshotting-1787" to be "Succeeded or Failed"
Sep 14 11:44:42.223: INFO: Pod "pvc-snapshottable-tester-d4jct": Phase="Pending", Reason="", readiness=false. Elapsed: 32.021686ms
Sep 14 11:44:44.256: INFO: Pod "pvc-snapshottable-tester-d4jct": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.065235456s
STEP: Saw pod success
Sep 14 11:44:44.256: INFO: Pod "pvc-snapshottable-tester-d4jct" satisfied condition "Succeeded or Failed"
Sep 14 11:44:44.323: INFO: Pod pvc-snapshottable-tester-d4jct has the following logs: 
Sep 14 11:44:44.323: INFO: Deleting pod "pvc-snapshottable-tester-d4jct" in namespace "snapshotting-1787"
Sep 14 11:44:44.364: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-d4jct" to be fully deleted
Sep 14 11:44:44.396: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comzj7gt] to have phase Bound
Sep 14 11:44:44.427: INFO: PersistentVolumeClaim test.csi.azure.comzj7gt found and phase=Bound (31.445536ms)
STEP: [init] checking the claim
... skipping 79 lines ...
Sep 14 11:44:50.062: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:44:50.096: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comwvt2p] to have phase Bound
Sep 14 11:44:50.128: INFO: PersistentVolumeClaim test.csi.azure.comwvt2p found but phase is Pending instead of Bound.
Sep 14 11:44:52.161: INFO: PersistentVolumeClaim test.csi.azure.comwvt2p found and phase=Bound (2.065043573s)
STEP: Creating pod pod-subpath-test-dynamicpv-kzvh
STEP: Creating a pod to test subpath
Sep 14 11:44:52.267: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-kzvh" in namespace "provisioning-4641" to be "Succeeded or Failed"
Sep 14 11:44:52.299: INFO: Pod "pod-subpath-test-dynamicpv-kzvh": Phase="Pending", Reason="", readiness=false. Elapsed: 31.957515ms
Sep 14 11:44:54.332: INFO: Pod "pod-subpath-test-dynamicpv-kzvh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.064735508s
Sep 14 11:44:56.365: INFO: Pod "pod-subpath-test-dynamicpv-kzvh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.097229643s
STEP: Saw pod success
Sep 14 11:44:56.365: INFO: Pod "pod-subpath-test-dynamicpv-kzvh" satisfied condition "Succeeded or Failed"
Sep 14 11:44:56.397: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000000 pod pod-subpath-test-dynamicpv-kzvh container test-container-volume-dynamicpv-kzvh: <nil>
STEP: delete the pod
Sep 14 11:44:56.469: INFO: Waiting for pod pod-subpath-test-dynamicpv-kzvh to disappear
Sep 14 11:44:56.501: INFO: Pod pod-subpath-test-dynamicpv-kzvh no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-kzvh
Sep 14 11:44:56.501: INFO: Deleting pod "pod-subpath-test-dynamicpv-kzvh" in namespace "provisioning-4641"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support existing directory
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:205
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support existing directory","total":28,"completed":3,"skipped":780,"failed":1,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents"]}

SSSSSS
------------------------------
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 in first pod, new pod with different fsgroup applied to the volume contents
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208
... skipping 22 lines ...
Sep 14 11:41:41.837: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/file1] Namespace:fsgroupchangepolicy-5556 PodName:pod-b895b7a8-7837-4459-af46-d23e5ed28ca8 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:41:41.837: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:41:42.288: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/file1] Namespace:fsgroupchangepolicy-5556 PodName:pod-b895b7a8-7837-4459-af46-d23e5ed28ca8 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:41:42.288: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:41:42.635: INFO: pod fsgroupchangepolicy-5556/pod-b895b7a8-7837-4459-af46-d23e5ed28ca8 exec for cmd ls -l /mnt/volume1/file1, stdout: -rw-r--r--    1 root     root             0 Sep 14 11:41 /mnt/volume1/file1, stderr: 
Sep 14 11:41:42.635: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 14 11:41 /mnt/volume1/file1], expected gid: 1000
Sep 14 11:41:42.635: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc003d9b760, 0x709327d, 0x12, 0xc004a10c58, 0x4, 0xc0034b3800)
... skipping 71 lines ...
Sep 14 11:46:19.539: INFO: PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 found and phase=Bound (4m36.870406166s)
Sep 14 11:46:24.572: INFO: PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 found and phase=Bound (4m41.90281416s)
Sep 14 11:46:29.604: INFO: PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 found and phase=Bound (4m46.935254098s)
Sep 14 11:46:34.638: INFO: PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 found and phase=Bound (4m51.968898927s)
Sep 14 11:46:39.670: INFO: PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 found and phase=Bound (4m57.001743352s)
STEP: Deleting sc
Sep 14 11:46:44.705: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 not deleted by dynamic provisioner: PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-ebd137eb-7054-465e-8350-eb46a51d3dc5 still exists within 5m0s",
... skipping 6 lines ...

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/testsuites.(*fsGroupChangePolicyTestSuite).DefineTests.func2()
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:132 +0xf0
panic(0x6bf5d00, 0xc0043a8bc0)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc000c1ca50, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc003207900, 0x499)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:63 +0xa5
panic(0x6323060, 0x77ced70)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc000c1ca50, 0x4c, 0xc00319ac38, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:67 +0x1b5
k8s.io/kubernetes/test/e2e/framework.Fail(0xc000e495c0, 0x37, 0xc00321ff80, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/log.go:62 +0x1ea
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).match(0xc00319adc0, 0x7904368, 0xc0043c1460, 0x1, 0x0, 0x0, 0x0, 0xc0043c1460)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:79 +0x216
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc00319adc0, 0x7904368, 0xc0043c1460, 0x0, 0x0, 0x0, 0xc000500000)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework.ExpectEqual(0x6323060, 0xc0043c1440, 0x6323060, 0xc0043c1450, 0x0, 0x0, 0x0)
... skipping 138 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED 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 in first pod, new pod with different fsgroup applied to the volume contents","total":19,"completed":3,"skipped":871,"failed":1,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents"]}

SSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:46:45.861: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 74 lines ...
Sep 14 11:44:44.998: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/file1] Namespace:fsgroupchangepolicy-4842 PodName:pod-eb0fa589-7f43-4ec9-af02-93eb547289e3 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:44:44.998: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:44:45.404: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/file1] Namespace:fsgroupchangepolicy-4842 PodName:pod-eb0fa589-7f43-4ec9-af02-93eb547289e3 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:44:45.404: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:44:45.774: INFO: pod fsgroupchangepolicy-4842/pod-eb0fa589-7f43-4ec9-af02-93eb547289e3 exec for cmd ls -l /mnt/volume1/file1, stdout: -rw-r--r--    1 root     root             0 Sep 14 11:44 /mnt/volume1/file1, stderr: 
Sep 14 11:44:45.774: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 14 11:44 /mnt/volume1/file1], expected gid: 1000
Sep 14 11:44:45.775: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc001ada580, 0x709327d, 0x12, 0xc003b7f368, 0x4, 0xc003fa0400)
... skipping 71 lines ...
Sep 14 11:49:22.696: INFO: PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd found and phase=Bound (4m36.888441544s)
Sep 14 11:49:27.730: INFO: PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd found and phase=Bound (4m41.922239496s)
Sep 14 11:49:32.762: INFO: PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd found and phase=Bound (4m46.954433871s)
Sep 14 11:49:37.794: INFO: PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd found and phase=Bound (4m51.98647532s)
Sep 14 11:49:42.830: INFO: PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd found and phase=Bound (4m57.022170703s)
STEP: Deleting sc
Sep 14 11:49:47.866: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd not deleted by dynamic provisioner: PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-02f89f23-f41f-4adb-b8c3-a6358824a7cd still exists within 5m0s",
... skipping 6 lines ...

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/testsuites.(*fsGroupChangePolicyTestSuite).DefineTests.func2()
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:132 +0xf0
panic(0x6bf5d00, 0xc002d6d240)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc003c65680, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc003fc3900, 0x499)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:63 +0xa5
panic(0x6323060, 0x77ced70)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc003c65680, 0x4c, 0xc002cb6c38, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:67 +0x1b5
k8s.io/kubernetes/test/e2e/framework.Fail(0xc0040fdf40, 0x37, 0xc0042cdc40, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/log.go:62 +0x1ea
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).match(0xc002cb6dc0, 0x7904368, 0xc0042ec1b0, 0x1, 0x0, 0x0, 0x0, 0xc0042ec1b0)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:79 +0x216
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc002cb6dc0, 0x7904368, 0xc0042ec1b0, 0x0, 0x0, 0x0, 0xc000092c00)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework.ExpectEqual(0x6323060, 0xc0042ec190, 0x6323060, 0xc0042ec1a0, 0x0, 0x0, 0x0)
... skipping 136 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED 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 in first pod, new pod with same fsgroup applied to the volume contents","total":18,"completed":1,"skipped":514,"failed":2,"failures":["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 in first pod, new pod with same fsgroup skips ownership changes to the volume contents","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 in first pod, new pod with same fsgroup applied to the volume contents"]}

SSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:49:49.035: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 52 lines ...
STEP: creating a claim
Sep 14 11:49:49.283: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:49:49.317: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comfd7sg] to have phase Bound
Sep 14 11:49:49.349: INFO: PersistentVolumeClaim test.csi.azure.comfd7sg found but phase is Pending instead of Bound.
Sep 14 11:49:51.382: INFO: PersistentVolumeClaim test.csi.azure.comfd7sg found and phase=Bound (2.065079752s)
STEP: [init] starting a pod to use the claim
Sep 14 11:49:51.480: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-68f26" in namespace "snapshotting-2996" to be "Succeeded or Failed"
Sep 14 11:49:51.513: INFO: Pod "pvc-snapshottable-tester-68f26": Phase="Pending", Reason="", readiness=false. Elapsed: 33.187975ms
Sep 14 11:49:53.545: INFO: Pod "pvc-snapshottable-tester-68f26": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.065637041s
STEP: Saw pod success
Sep 14 11:49:53.545: INFO: Pod "pvc-snapshottable-tester-68f26" satisfied condition "Succeeded or Failed"
Sep 14 11:49:53.611: INFO: Pod pvc-snapshottable-tester-68f26 has the following logs: 
Sep 14 11:49:53.611: INFO: Deleting pod "pvc-snapshottable-tester-68f26" in namespace "snapshotting-2996"
Sep 14 11:49:53.650: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-68f26" to be fully deleted
Sep 14 11:49:53.681: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comfd7sg] to have phase Bound
Sep 14 11:49:53.713: INFO: PersistentVolumeClaim test.csi.azure.comfd7sg found and phase=Bound (31.446734ms)
STEP: [init] checking the claim
... skipping 87 lines ...
Sep 14 11:45:06.294: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/file1] Namespace:fsgroupchangepolicy-4489 PodName:pod-bdd198a8-8d32-4834-998d-7a801a422547 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:45:06.294: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:45:06.706: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/file1] Namespace:fsgroupchangepolicy-4489 PodName:pod-bdd198a8-8d32-4834-998d-7a801a422547 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 14 11:45:06.706: INFO: >>> kubeConfig: /root/tmp331652305/kubeconfig/kubeconfig.eastus2.json
Sep 14 11:45:07.135: INFO: pod fsgroupchangepolicy-4489/pod-bdd198a8-8d32-4834-998d-7a801a422547 exec for cmd ls -l /mnt/volume1/file1, stdout: -rw-r--r--    1 root     root             0 Sep 14 11:45 /mnt/volume1/file1, stderr: 
Sep 14 11:45:07.135: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 14 11:45 /mnt/volume1/file1], expected gid: 1000
Sep 14 11:45:07.136: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc003e71760, 0x709327d, 0x12, 0xc00329aa18, 0x4, 0xc002d14800)
... skipping 71 lines ...
Sep 14 11:49:44.108: INFO: PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 found and phase=Bound (4m36.937436508s)
Sep 14 11:49:49.140: INFO: PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 found and phase=Bound (4m41.970094289s)
Sep 14 11:49:54.173: INFO: PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 found and phase=Bound (4m47.00264973s)
Sep 14 11:49:59.206: INFO: PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 found and phase=Bound (4m52.035702372s)
Sep 14 11:50:04.238: INFO: PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 found and phase=Bound (4m57.068177486s)
STEP: Deleting sc
Sep 14 11:50:09.273: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 not deleted by dynamic provisioner: PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-72bcb8a8-645c-42e4-ae95-ebcfa4f772f3 still exists within 5m0s",
... skipping 6 lines ...

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/testsuites.(*fsGroupChangePolicyTestSuite).DefineTests.func2()
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:132 +0xf0
panic(0x6bf5d00, 0xc003e2d140)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc00406a870, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc003317400, 0x499)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:63 +0xa5
panic(0x6323060, 0x77ced70)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc00406a870, 0x4c, 0xc002b8cc38, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/ginkgowrapper/wrapper.go:67 +0x1b5
k8s.io/kubernetes/test/e2e/framework.Fail(0xc003d1af00, 0x37, 0xc004bcbc60, 0x1, 0x1)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/log.go:62 +0x1ea
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).match(0xc002b8cdc0, 0x7904368, 0xc0025afe60, 0x1, 0x0, 0x0, 0x0, 0xc0025afe60)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:79 +0x216
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc002b8cdc0, 0x7904368, 0xc0025afe60, 0x0, 0x0, 0x0, 0xc000188400)
	/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework.ExpectEqual(0x6323060, 0xc0025afe40, 0x6323060, 0xc0025afe50, 0x0, 0x0, 0x0)
... skipping 137 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED 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":28,"completed":3,"skipped":786,"failed":2,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents","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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode 
  should not mount / map unused volumes in a pod [LinuxOnly]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:351
... skipping 48 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should not mount / map unused volumes in a pod [LinuxOnly]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:351
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode should not mount / map unused volumes in a pod [LinuxOnly]","total":28,"completed":4,"skipped":835,"failed":2,"failures":["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 in first pod, new pod with different fsgroup applied to the volume contents","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"]}

SSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] volume-expand
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:50:25.557: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 77 lines ...
Sep 14 11:49:59.493: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 14 11:49:59.526: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.commt2k7] to have phase Bound
Sep 14 11:49:59.558: INFO: PersistentVolumeClaim test.csi.azure.commt2k7 found but phase is Pending instead of Bound.
Sep 14 11:50:01.591: INFO: PersistentVolumeClaim test.csi.azure.commt2k7 found and phase=Bound (2.065031536s)
STEP: Creating pod pod-subpath-test-dynamicpv-95qp
STEP: Creating a pod to test atomic-volume-subpath
Sep 14 11:50:01.688: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-95qp" in namespace "provisioning-3047" to be "Succeeded or Failed"
Sep 14 11:50:01.720: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Pending", Reason="", readiness=false. Elapsed: 31.702508ms
Sep 14 11:50:03.756: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.068214487s
Sep 14 11:50:05.791: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 4.102782789s
Sep 14 11:50:07.823: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 6.135111644s
Sep 14 11:50:09.856: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 8.168173501s
Sep 14 11:50:11.890: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 10.201738696s
... skipping 2 lines ...
Sep 14 11:50:17.990: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 16.301810563s
Sep 14 11:50:20.024: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 18.335573303s
Sep 14 11:50:22.056: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 20.368101559s
Sep 14 11:50:24.089: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Running", Reason="", readiness=true. Elapsed: 22.401239803s
Sep 14 11:50:26.123: INFO: Pod "pod-subpath-test-dynamicpv-95qp": Phase="Succeeded", Reason="", readiness=false. Elapsed: 24.434441924s
STEP: Saw pod success
Sep 14 11:50:26.123: INFO: Pod "pod-subpath-test-dynamicpv-95qp" satisfied condition "Succeeded or Failed"
Sep 14 11:50:26.155: INFO: Trying to get logs from node k8s-agentpool1-30981978-vmss000001 pod pod-subpath-test-dynamicpv-95qp container test-container-subpath-dynamicpv-95qp: <nil>
STEP: delete the pod
Sep 14 11:50:26.227: INFO: Waiting for pod pod-subpath-test-dynamicpv-95qp to disappear
Sep 14 11:50:26.259: INFO: Pod pod-subpath-test-dynamicpv-95qp no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-95qp
Sep 14 11:50:26.259: INFO: Deleting pod "pod-subpath-test-dynamicpv-95qp" in namespace "provisioning-3047"
... skipping 16 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Dynamic PV (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50
    should support file as subpath [LinuxOnly]
    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:230
------------------------------
{"msg":"PASSED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath should support file as subpath [LinuxOnly]","total":18,"completed":2,"skipped":835,"failed":2,"failures":["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 in first pod, new pod with same fsgroup skips ownership changes to the volume contents","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 in first pod, new pod with same fsgroup applied to the volume contents"]}

SSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (ext3)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 14 11:50:31.562: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 66 lines ...
Sep 14 11:50:31.668: INFO: Running AfterSuite actions on node 1



Summarizing 6 Failures:

[Fail] External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [Measurement] (Always)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

[Fail] External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [Measurement] (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

[Fail] External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [Measurement] (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with same fsgroup skips ownership changes to the volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

[Fail] External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [Measurement] (Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

[Fail] External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [Measurement] (Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with same fsgroup applied to the volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

[Fail] External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [Measurement] (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

Ran 27 of 6666 Specs in 753.750 seconds
FAIL! -- 21 Passed | 6 Failed | 0 Pending | 6639 Skipped 

Ginkgo ran 1 suite in 12m38.182374233s
Test Suite Failed
+ print_logs
+ bash ./hack/verify-examples.sh linux
begin to create deployment examples ...
storageclass.storage.k8s.io/azurefile-csi created
Applying config "deploy/example/daemonset.yaml"
Waiting for daemon set "daemonset-azurefile" rollout to finish: 0 of 2 updated pods are available...
... skipping 68 lines ...
Go Version: go1.17
Platform: linux/amd64

Streaming logs below:
I0914 11:37:49.088010       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 gc/go1.17 (amd64-linux) e2e-test
I0914 11:37:49.090595       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0914 11:37:49.115128       1 azure.go:77] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0914 11:37:49.115148       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0914 11:37:49.115166       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0914 11:37:49.115186       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0914 11:37:49.115786       1 azure_auth.go:234] Using AzurePublicCloud environment
I0914 11:37:49.115832       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0914 11:37:49.115852       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 640 lines ...
Go Version: go1.17
Platform: linux/amd64

Streaming logs below:
I0914 11:37:51.547827       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 gc/go1.17 (amd64-linux) e2e-test
I0914 11:37:51.549048       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0914 11:37:51.591743       1 azure.go:77] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0914 11:37:51.591766       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0914 11:37:51.591772       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0914 11:37:51.591798       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0914 11:37:51.592414       1 azure_auth.go:234] Using AzurePublicCloud environment
I0914 11:37:51.592457       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0914 11:37:51.592483       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 99 lines ...
Go Version: go1.17
Platform: linux/amd64

Streaming logs below:
I0914 11:37:43.794468       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 gc/go1.17 (amd64-linux) e2e-test
I0914 11:37:43.795934       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0914 11:37:43.819016       1 azure.go:77] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0914 11:37:43.819033       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0914 11:37:43.819039       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0914 11:37:43.819057       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0914 11:37:43.819991       1 azure_auth.go:234] Using AzurePublicCloud environment
I0914 11:37:43.820026       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0914 11:37:43.820050       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 457 lines ...
Go Version: go1.17
Platform: linux/amd64

Streaming logs below:
I0914 11:37:46.058385       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 gc/go1.17 (amd64-linux) e2e-test
I0914 11:37:46.059750       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0914 11:37:46.087765       1 azure.go:77] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0914 11:37:46.087788       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0914 11:37:46.087794       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0914 11:37:46.087811       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0914 11:37:46.088392       1 azure_auth.go:234] Using AzurePublicCloud environment
I0914 11:37:46.088476       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0914 11:37:46.088643       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 814 lines ...
Go Version: go1.17
Platform: linux/amd64

Streaming logs below:
I0914 11:37:40.137459       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-80a180586d0bbf0275aa10e601cb4ab5bc334c96 gc/go1.17 (amd64-linux) e2e-test
I0914 11:37:40.138393       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0914 11:37:40.160494       1 azure.go:77] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0914 11:37:40.160512       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0914 11:37:40.160518       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0914 11:37:40.160535       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0914 11:37:40.161105       1 azure_auth.go:234] Using AzurePublicCloud environment
I0914 11:37:40.161140       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0914 11:37:40.161174       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 390 lines ...
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 7.6214272e+08
# HELP process_virtual_memory_max_bytes Maximum amount of virtual memory available in bytes.
# TYPE process_virtual_memory_max_bytes gauge
process_virtual_memory_max_bytes -1
make: *** [Makefile:85: e2e-test] Error 1
2021/09/14 11:51:18 process.go:155: Step 'make e2e-test' finished in 22m0.129680343s
2021/09/14 11:51:18 aksengine_helpers.go:425: downloading /root/tmp331652305/log-dump.sh from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh
2021/09/14 11:51:18 util.go:68: curl https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh
2021/09/14 11:51:18 process.go:153: Running: chmod +x /root/tmp331652305/log-dump.sh
2021/09/14 11:51:18 process.go:155: Step 'chmod +x /root/tmp331652305/log-dump.sh' finished in 1.217416ms
2021/09/14 11:51:18 aksengine_helpers.go:425: downloading /root/tmp331652305/log-dump-daemonset.yaml from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump-daemonset.yaml
... skipping 53 lines ...
ssh key file /root/.ssh/id_rsa does not exist. Exiting.
2021/09/14 11:51:45 process.go:155: Step 'bash -c /root/tmp331652305/win-ci-logs-collector.sh kubetest-f8slwdln.eastus2.cloudapp.azure.com /root/tmp331652305 /root/.ssh/id_rsa' finished in 3.478538ms
2021/09/14 11:51:45 aksengine.go:1141: Deleting resource group: kubetest-f8slwdln.
2021/09/14 11:57:49 process.go:96: Saved XML output to /logs/artifacts/junit_runner.xml.
2021/09/14 11:57:49 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
2021/09/14 11:57:49 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 285.422407ms
2021/09/14 11:57:49 main.go:331: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2]
+ EXIT_VALUE=1
+ set +o xtrace
Cleaning up after docker in docker.
================================================================================
Cleaning up after docker
b8666cf3bf18
... skipping 4 lines ...