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-16 11:51
Elapsed35m24s
Revision371cca3ccee8013850503992faa3558974615935
Refs 759
job-versionv1.23.0-alpha.2.41+0734820279ccce
kubetest-version
revisionv1.23.0-alpha.2.41+0734820279ccce

Test Failures


kubetest Test 21m53s

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 223 lines ...

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100 11248  100 11248    0     0   119k      0 --:--:-- --:--:-- --:--:--  119k
Downloading https://get.helm.sh/helm-v3.7.0-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull k8sprow.azurecr.io/azurefile-csi:e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 || make container-all push-manifest
Error response from daemon: manifest for k8sprow.azurecr.io/azurefile-csi:e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 not found: manifest unknown: manifest tagged by "e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0" 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-5c798c110cb3a820e89f51e394bd67e540cbddf0 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=5c798c110cb3a820e89f51e394bd67e540cbddf0 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2021-09-16T11:56:22Z -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 1679 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 575 lines ...
Sep 16 12:05:56.752: INFO: PersistentVolumeClaim test.csi.azure.compt6j5 found but phase is Pending instead of Bound.
Sep 16 12:05:58.790: INFO: PersistentVolumeClaim test.csi.azure.compt6j5 found but phase is Pending instead of Bound.
Sep 16 12:06:00.829: INFO: PersistentVolumeClaim test.csi.azure.compt6j5 found but phase is Pending instead of Bound.
Sep 16 12:06:02.868: INFO: PersistentVolumeClaim test.csi.azure.compt6j5 found and phase=Bound (55.065098506s)
STEP: Creating pod pod-subpath-test-dynamicpv-bcrj
STEP: Creating a pod to test subpath
Sep 16 12:06:02.984: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-bcrj" in namespace "provisioning-4637" to be "Succeeded or Failed"
Sep 16 12:06:03.022: INFO: Pod "pod-subpath-test-dynamicpv-bcrj": Phase="Pending", Reason="", readiness=false. Elapsed: 37.321024ms
Sep 16 12:06:05.060: INFO: Pod "pod-subpath-test-dynamicpv-bcrj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076062546s
Sep 16 12:06:07.098: INFO: Pod "pod-subpath-test-dynamicpv-bcrj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.114035801s
Sep 16 12:06:09.137: INFO: Pod "pod-subpath-test-dynamicpv-bcrj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.152301723s
Sep 16 12:06:11.176: INFO: Pod "pod-subpath-test-dynamicpv-bcrj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.19137735s
Sep 16 12:06:13.214: INFO: Pod "pod-subpath-test-dynamicpv-bcrj": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.229645867s
STEP: Saw pod success
Sep 16 12:06:13.214: INFO: Pod "pod-subpath-test-dynamicpv-bcrj" satisfied condition "Succeeded or Failed"
Sep 16 12:06:13.252: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-bcrj container test-container-subpath-dynamicpv-bcrj: <nil>
STEP: delete the pod
Sep 16 12:06:13.336: INFO: Waiting for pod pod-subpath-test-dynamicpv-bcrj to disappear
Sep 16 12:06:13.373: INFO: Pod pod-subpath-test-dynamicpv-bcrj no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-bcrj
Sep 16 12:06:13.373: INFO: Deleting pod "pod-subpath-test-dynamicpv-bcrj" in namespace "provisioning-4637"
... 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":16,"completed":1,"skipped":212,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 16 12:06:18.907: INFO: Driver "test.csi.azure.com" does not support block volume mode - skipping
... skipping 65 lines ...
Sep 16 12:05:56.355: INFO: PersistentVolumeClaim test.csi.azure.comfb64k found but phase is Pending instead of Bound.
Sep 16 12:05:58.392: INFO: PersistentVolumeClaim test.csi.azure.comfb64k found but phase is Pending instead of Bound.
Sep 16 12:06:00.428: INFO: PersistentVolumeClaim test.csi.azure.comfb64k found but phase is Pending instead of Bound.
Sep 16 12:06:02.466: INFO: PersistentVolumeClaim test.csi.azure.comfb64k found and phase=Bound (55.057707452s)
STEP: Creating pod pod-subpath-test-dynamicpv-8pfl
STEP: Creating a pod to test subpath
Sep 16 12:06:02.583: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-8pfl" in namespace "provisioning-2876" to be "Succeeded or Failed"
Sep 16 12:06:02.623: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Pending", Reason="", readiness=false. Elapsed: 40.572861ms
Sep 16 12:06:04.662: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Pending", Reason="", readiness=false. Elapsed: 2.079143592s
Sep 16 12:06:06.701: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Pending", Reason="", readiness=false. Elapsed: 4.1181868s
Sep 16 12:06:08.740: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Pending", Reason="", readiness=false. Elapsed: 6.15671426s
Sep 16 12:06:10.779: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Pending", Reason="", readiness=false. Elapsed: 8.196332429s
Sep 16 12:06:12.817: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Pending", Reason="", readiness=false. Elapsed: 10.234368993s
Sep 16 12:06:14.855: INFO: Pod "pod-subpath-test-dynamicpv-8pfl": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.272324076s
STEP: Saw pod success
Sep 16 12:06:14.855: INFO: Pod "pod-subpath-test-dynamicpv-8pfl" satisfied condition "Succeeded or Failed"
Sep 16 12:06:14.893: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-8pfl container test-container-subpath-dynamicpv-8pfl: <nil>
STEP: delete the pod
Sep 16 12:06:14.979: INFO: Waiting for pod pod-subpath-test-dynamicpv-8pfl to disappear
Sep 16 12:06:15.016: INFO: Pod pod-subpath-test-dynamicpv-8pfl no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-8pfl
Sep 16 12:06:15.017: INFO: Deleting pod "pod-subpath-test-dynamicpv-8pfl" in namespace "provisioning-2876"
... 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":11,"completed":1,"skipped":177,"failed":0}

S
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] subPath
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:06:20.380: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 65 lines ...
Sep 16 12:05:56.726: INFO: PersistentVolumeClaim test.csi.azure.comfrs9c found but phase is Pending instead of Bound.
Sep 16 12:05:58.762: INFO: PersistentVolumeClaim test.csi.azure.comfrs9c found but phase is Pending instead of Bound.
Sep 16 12:06:00.798: INFO: PersistentVolumeClaim test.csi.azure.comfrs9c found but phase is Pending instead of Bound.
Sep 16 12:06:02.834: INFO: PersistentVolumeClaim test.csi.azure.comfrs9c found and phase=Bound (55.054818814s)
STEP: Creating pod pod-subpath-test-dynamicpv-xshh
STEP: Creating a pod to test subpath
Sep 16 12:06:02.947: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-xshh" in namespace "provisioning-4031" to be "Succeeded or Failed"
Sep 16 12:06:02.983: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Pending", Reason="", readiness=false. Elapsed: 36.096017ms
Sep 16 12:06:05.020: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Pending", Reason="", readiness=false. Elapsed: 2.072539303s
Sep 16 12:06:07.056: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Pending", Reason="", readiness=false. Elapsed: 4.108743257s
Sep 16 12:06:09.093: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Pending", Reason="", readiness=false. Elapsed: 6.145460454s
Sep 16 12:06:11.129: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Pending", Reason="", readiness=false. Elapsed: 8.182091942s
Sep 16 12:06:13.168: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Pending", Reason="", readiness=false. Elapsed: 10.220694598s
Sep 16 12:06:15.204: INFO: Pod "pod-subpath-test-dynamicpv-xshh": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.256822411s
STEP: Saw pod success
Sep 16 12:06:15.204: INFO: Pod "pod-subpath-test-dynamicpv-xshh" satisfied condition "Succeeded or Failed"
Sep 16 12:06:15.240: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-xshh container test-container-subpath-dynamicpv-xshh: <nil>
STEP: delete the pod
Sep 16 12:06:15.331: INFO: Waiting for pod pod-subpath-test-dynamicpv-xshh to disappear
Sep 16 12:06:15.368: INFO: Pod pod-subpath-test-dynamicpv-xshh no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-xshh
Sep 16 12:06:15.368: INFO: Deleting pod "pod-subpath-test-dynamicpv-xshh" in namespace "provisioning-4031"
... 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":20,"completed":1,"skipped":159,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 16 12:06:20.757: INFO: Driver test.csi.azure.com doesn't support ext4 -- skipping
... skipping 116 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":13,"completed":1,"skipped":189,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (ext4)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:06:23.076: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 111 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":20,"completed":2,"skipped":251,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (default fs)] provisioning
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] provisioning
... skipping 93 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":17,"completed":1,"skipped":278,"failed":0}

SSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral 
  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
... skipping 39 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":18,"completed":1,"skipped":7,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 16 12:06:42.121: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 45 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 165 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 20 lines ...
Sep 16 12:06:39.412: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:06:39.452: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.compj87h] to have phase Bound
Sep 16 12:06:39.490: INFO: PersistentVolumeClaim test.csi.azure.compj87h found but phase is Pending instead of Bound.
Sep 16 12:06:41.528: INFO: PersistentVolumeClaim test.csi.azure.compj87h found and phase=Bound (2.076027181s)
STEP: Creating pod pod-subpath-test-dynamicpv-fjrk
STEP: Creating a pod to test subpath
Sep 16 12:06:41.650: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-fjrk" in namespace "provisioning-5227" to be "Succeeded or Failed"
Sep 16 12:06:41.688: INFO: Pod "pod-subpath-test-dynamicpv-fjrk": Phase="Pending", Reason="", readiness=false. Elapsed: 37.561837ms
Sep 16 12:06:43.728: INFO: Pod "pod-subpath-test-dynamicpv-fjrk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.077380852s
Sep 16 12:06:45.767: INFO: Pod "pod-subpath-test-dynamicpv-fjrk": Phase="Pending", Reason="", readiness=false. Elapsed: 4.117152967s
Sep 16 12:06:47.807: INFO: Pod "pod-subpath-test-dynamicpv-fjrk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.156863155s
STEP: Saw pod success
Sep 16 12:06:47.807: INFO: Pod "pod-subpath-test-dynamicpv-fjrk" satisfied condition "Succeeded or Failed"
Sep 16 12:06:47.845: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-fjrk container test-container-volume-dynamicpv-fjrk: <nil>
STEP: delete the pod
Sep 16 12:06:47.931: INFO: Waiting for pod pod-subpath-test-dynamicpv-fjrk to disappear
Sep 16 12:06:47.968: INFO: Pod pod-subpath-test-dynamicpv-fjrk no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-fjrk
Sep 16 12:06:47.968: INFO: Deleting pod "pod-subpath-test-dynamicpv-fjrk" in namespace "provisioning-5227"
... 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":17,"completed":2,"skipped":296,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:06:53.356: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 114 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":16,"completed":2,"skipped":333,"failed":0}

SSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (ext3)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:06:56.395: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 57 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":11,"completed":2,"skipped":270,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
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
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_expand.go:246
... skipping 42 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":17,"completed":3,"skipped":390,"failed":0}

SSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] provisioning
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:07:07.652: INFO: Driver test.csi.azure.com doesn't support Block -- skipping
... skipping 162 lines ...
Sep 16 12:06:56.822: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:06:56.861: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com9wgpw] to have phase Bound
Sep 16 12:06:56.898: INFO: PersistentVolumeClaim test.csi.azure.com9wgpw found but phase is Pending instead of Bound.
Sep 16 12:06:58.936: INFO: PersistentVolumeClaim test.csi.azure.com9wgpw found and phase=Bound (2.075048972s)
STEP: Creating pod pod-subpath-test-dynamicpv-nctv
STEP: Creating a pod to test subpath
Sep 16 12:06:59.070: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-nctv" in namespace "provisioning-4424" to be "Succeeded or Failed"
Sep 16 12:06:59.109: INFO: Pod "pod-subpath-test-dynamicpv-nctv": Phase="Pending", Reason="", readiness=false. Elapsed: 38.871566ms
Sep 16 12:07:01.147: INFO: Pod "pod-subpath-test-dynamicpv-nctv": Phase="Pending", Reason="", readiness=false. Elapsed: 2.076926195s
Sep 16 12:07:03.198: INFO: Pod "pod-subpath-test-dynamicpv-nctv": Phase="Pending", Reason="", readiness=false. Elapsed: 4.128014294s
Sep 16 12:07:05.237: INFO: Pod "pod-subpath-test-dynamicpv-nctv": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.166830447s
STEP: Saw pod success
Sep 16 12:07:05.237: INFO: Pod "pod-subpath-test-dynamicpv-nctv" satisfied condition "Succeeded or Failed"
Sep 16 12:07:05.274: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-nctv container test-container-volume-dynamicpv-nctv: <nil>
STEP: delete the pod
Sep 16 12:07:05.362: INFO: Waiting for pod pod-subpath-test-dynamicpv-nctv to disappear
Sep 16 12:07:05.398: INFO: Pod pod-subpath-test-dynamicpv-nctv no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-nctv
Sep 16 12:07:05.398: INFO: Deleting pod "pod-subpath-test-dynamicpv-nctv" in namespace "provisioning-4424"
... 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":16,"completed":3,"skipped":542,"failed":0}

SSSSSS
------------------------------
[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 16 12:07:10.974: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:07:11.016: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comqz77c] to have phase Bound
Sep 16 12:07:11.053: INFO: PersistentVolumeClaim test.csi.azure.comqz77c found but phase is Pending instead of Bound.
Sep 16 12:07:13.092: INFO: PersistentVolumeClaim test.csi.azure.comqz77c found and phase=Bound (2.076332736s)
STEP: [init] starting a pod to use the claim
Sep 16 12:07:13.208: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-pc7fz" in namespace "snapshotting-312" to be "Succeeded or Failed"
Sep 16 12:07:13.247: INFO: Pod "pvc-snapshottable-tester-pc7fz": Phase="Pending", Reason="", readiness=false. Elapsed: 38.389049ms
Sep 16 12:07:15.286: INFO: Pod "pvc-snapshottable-tester-pc7fz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.077572313s
STEP: Saw pod success
Sep 16 12:07:15.286: INFO: Pod "pvc-snapshottable-tester-pc7fz" satisfied condition "Succeeded or Failed"
Sep 16 12:07:15.366: INFO: Pod pvc-snapshottable-tester-pc7fz has the following logs: 
Sep 16 12:07:15.366: INFO: Deleting pod "pvc-snapshottable-tester-pc7fz" in namespace "snapshotting-312"
Sep 16 12:07:15.410: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-pc7fz" to be fully deleted
Sep 16 12:07:15.448: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comqz77c] to have phase Bound
Sep 16 12:07:15.486: INFO: PersistentVolumeClaim test.csi.azure.comqz77c found and phase=Bound (37.933563ms)
STEP: [init] checking the claim
... skipping 101 lines ...
Sep 16 12:07:00.551: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:07:00.591: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comtrmqz] to have phase Bound
Sep 16 12:07:00.629: INFO: PersistentVolumeClaim test.csi.azure.comtrmqz found but phase is Pending instead of Bound.
Sep 16 12:07:02.668: INFO: PersistentVolumeClaim test.csi.azure.comtrmqz found and phase=Bound (2.076522769s)
STEP: Creating pod pod-subpath-test-dynamicpv-rz9n
STEP: Creating a pod to test atomic-volume-subpath
Sep 16 12:07:02.783: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-rz9n" in namespace "provisioning-7658" to be "Succeeded or Failed"
Sep 16 12:07:02.821: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Pending", Reason="", readiness=false. Elapsed: 37.733347ms
Sep 16 12:07:04.862: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Pending", Reason="", readiness=false. Elapsed: 2.078582689s
Sep 16 12:07:06.902: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Pending", Reason="", readiness=false. Elapsed: 4.11864539s
Sep 16 12:07:08.941: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Pending", Reason="", readiness=false. Elapsed: 6.157681704s
Sep 16 12:07:10.979: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Running", Reason="", readiness=true. Elapsed: 8.195626182s
Sep 16 12:07:13.018: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Running", Reason="", readiness=true. Elapsed: 10.234637749s
... skipping 4 lines ...
Sep 16 12:07:23.219: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Running", Reason="", readiness=true. Elapsed: 20.435528471s
Sep 16 12:07:25.258: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Running", Reason="", readiness=true. Elapsed: 22.474378496s
Sep 16 12:07:27.300: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Running", Reason="", readiness=true. Elapsed: 24.516478864s
Sep 16 12:07:29.338: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Running", Reason="", readiness=true. Elapsed: 26.555138523s
Sep 16 12:07:31.377: INFO: Pod "pod-subpath-test-dynamicpv-rz9n": Phase="Succeeded", Reason="", readiness=false. Elapsed: 28.593716249s
STEP: Saw pod success
Sep 16 12:07:31.377: INFO: Pod "pod-subpath-test-dynamicpv-rz9n" satisfied condition "Succeeded or Failed"
Sep 16 12:07:31.415: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000000 pod pod-subpath-test-dynamicpv-rz9n container test-container-subpath-dynamicpv-rz9n: <nil>
STEP: delete the pod
Sep 16 12:07:31.499: INFO: Waiting for pod pod-subpath-test-dynamicpv-rz9n to disappear
Sep 16 12:07:31.540: INFO: Pod pod-subpath-test-dynamicpv-rz9n no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-rz9n
Sep 16 12:07:31.540: INFO: Deleting pod "pod-subpath-test-dynamicpv-rz9n" in namespace "provisioning-7658"
... 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":11,"completed":3,"skipped":407,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volume-expand 
  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
... skipping 15 lines ...
Sep 16 12:07:08.189: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:07:08.230: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comsqkhf] to have phase Bound
Sep 16 12:07:08.268: INFO: PersistentVolumeClaim test.csi.azure.comsqkhf found but phase is Pending instead of Bound.
Sep 16 12:07:10.308: INFO: PersistentVolumeClaim test.csi.azure.comsqkhf found and phase=Bound (2.077546607s)
STEP: Expanding non-expandable pvc
Sep 16 12:07:10.383: INFO: currentPvcSize {{5368709120 0} {<nil>} 5Gi BinarySI}, newSize {{6442450944 0} {<nil>}  BinarySI}
Sep 16 12:07:10.459: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:12.538: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:14.539: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:16.537: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:18.543: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:20.548: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:22.537: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:24.537: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:26.536: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:28.537: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:30.536: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:32.536: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:34.539: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:36.536: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:38.539: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:40.538: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 16 12:07:40.620: INFO: Error updating pvc test.csi.azure.comsqkhf: persistentvolumeclaims "test.csi.azure.comsqkhf" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
STEP: Deleting pvc
Sep 16 12:07:40.620: INFO: Deleting PersistentVolumeClaim "test.csi.azure.comsqkhf"
Sep 16 12:07:40.664: INFO: Waiting up to 5m0s for PersistentVolume pvc-5660d3f4-c36e-4d10-96e0-b8c548449b3d to get deleted
Sep 16 12:07:40.707: INFO: PersistentVolume pvc-5660d3f4-c36e-4d10-96e0-b8c548449b3d found and phase=Released (43.27988ms)
Sep 16 12:07:45.746: INFO: PersistentVolume pvc-5660d3f4-c36e-4d10-96e0-b8c548449b3d 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":17,"completed":4,"skipped":701,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (ext4)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:07:45.953: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 87 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":20,"completed":3,"skipped":352,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (ext4)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:07:52.848: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 99 lines ...
Sep 16 12:07:37.245: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:07:37.287: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comv2kwc] to have phase Bound
Sep 16 12:07:37.325: INFO: PersistentVolumeClaim test.csi.azure.comv2kwc found but phase is Pending instead of Bound.
Sep 16 12:07:39.363: INFO: PersistentVolumeClaim test.csi.azure.comv2kwc found and phase=Bound (2.076138262s)
STEP: Creating pod pod-subpath-test-dynamicpv-z2zs
STEP: Creating a pod to test subpath
Sep 16 12:07:39.483: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-z2zs" in namespace "provisioning-4801" to be "Succeeded or Failed"
Sep 16 12:07:39.522: INFO: Pod "pod-subpath-test-dynamicpv-z2zs": Phase="Pending", Reason="", readiness=false. Elapsed: 38.538522ms
Sep 16 12:07:41.562: INFO: Pod "pod-subpath-test-dynamicpv-z2zs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.078152725s
Sep 16 12:07:43.601: INFO: Pod "pod-subpath-test-dynamicpv-z2zs": Phase="Pending", Reason="", readiness=false. Elapsed: 4.11723418s
Sep 16 12:07:45.640: INFO: Pod "pod-subpath-test-dynamicpv-z2zs": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.156204227s
STEP: Saw pod success
Sep 16 12:07:45.640: INFO: Pod "pod-subpath-test-dynamicpv-z2zs" satisfied condition "Succeeded or Failed"
Sep 16 12:07:45.678: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-z2zs container test-container-subpath-dynamicpv-z2zs: <nil>
STEP: delete the pod
Sep 16 12:07:45.764: INFO: Waiting for pod pod-subpath-test-dynamicpv-z2zs to disappear
Sep 16 12:07:45.802: INFO: Pod pod-subpath-test-dynamicpv-z2zs no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-z2zs
Sep 16 12:07:45.802: INFO: Deleting pod "pod-subpath-test-dynamicpv-z2zs" in namespace "provisioning-4801"
STEP: Creating pod pod-subpath-test-dynamicpv-z2zs
STEP: Creating a pod to test subpath
Sep 16 12:07:45.880: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-z2zs" in namespace "provisioning-4801" to be "Succeeded or Failed"
Sep 16 12:07:45.918: INFO: Pod "pod-subpath-test-dynamicpv-z2zs": Phase="Pending", Reason="", readiness=false. Elapsed: 37.634449ms
Sep 16 12:07:47.957: INFO: Pod "pod-subpath-test-dynamicpv-z2zs": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.076687633s
STEP: Saw pod success
Sep 16 12:07:47.957: INFO: Pod "pod-subpath-test-dynamicpv-z2zs" satisfied condition "Succeeded or Failed"
Sep 16 12:07:47.995: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000001 pod pod-subpath-test-dynamicpv-z2zs container test-container-subpath-dynamicpv-z2zs: <nil>
STEP: delete the pod
Sep 16 12:07:48.082: INFO: Waiting for pod pod-subpath-test-dynamicpv-z2zs to disappear
Sep 16 12:07:48.120: INFO: Pod pod-subpath-test-dynamicpv-z2zs no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-z2zs
Sep 16 12:07:48.120: INFO: Deleting pod "pod-subpath-test-dynamicpv-z2zs" in namespace "provisioning-4801"
... 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":11,"completed":4,"skipped":539,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] provisioning
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:07:53.583: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 52 lines ...
STEP: creating a claim
Sep 16 12:07:53.272: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:07:53.311: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com9hzd2] to have phase Bound
Sep 16 12:07:53.346: INFO: PersistentVolumeClaim test.csi.azure.com9hzd2 found but phase is Pending instead of Bound.
Sep 16 12:07:55.384: INFO: PersistentVolumeClaim test.csi.azure.com9hzd2 found and phase=Bound (2.072612228s)
STEP: [init] starting a pod to use the claim
Sep 16 12:07:55.493: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-f77h5" in namespace "snapshotting-3668" to be "Succeeded or Failed"
Sep 16 12:07:55.528: INFO: Pod "pvc-snapshottable-tester-f77h5": Phase="Pending", Reason="", readiness=false. Elapsed: 35.487237ms
Sep 16 12:07:57.566: INFO: Pod "pvc-snapshottable-tester-f77h5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.072663747s
STEP: Saw pod success
Sep 16 12:07:57.566: INFO: Pod "pvc-snapshottable-tester-f77h5" satisfied condition "Succeeded or Failed"
Sep 16 12:07:57.644: INFO: Pod pvc-snapshottable-tester-f77h5 has the following logs: 
Sep 16 12:07:57.644: INFO: Deleting pod "pvc-snapshottable-tester-f77h5" in namespace "snapshotting-3668"
Sep 16 12:07:57.687: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-f77h5" to be fully deleted
Sep 16 12:07:57.722: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com9hzd2] to have phase Bound
Sep 16 12:07:57.759: INFO: PersistentVolumeClaim test.csi.azure.com9hzd2 found and phase=Bound (36.750396ms)
STEP: [init] checking the claim
... skipping 167 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":11,"completed":5,"skipped":829,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
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
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/ephemeral.go:183
... skipping 46 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":16,"completed":4,"skipped":662,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] volumeMode
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:08:44.512: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 31 lines ...
STEP: creating a claim
Sep 16 12:08:44.844: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:08:44.888: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvqqj9] to have phase Bound
Sep 16 12:08:44.925: INFO: PersistentVolumeClaim test.csi.azure.comvqqj9 found but phase is Pending instead of Bound.
Sep 16 12:08:46.965: INFO: PersistentVolumeClaim test.csi.azure.comvqqj9 found and phase=Bound (2.077089381s)
STEP: [init] starting a pod to use the claim
Sep 16 12:08:47.080: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-94lsg" in namespace "snapshotting-6175" to be "Succeeded or Failed"
Sep 16 12:08:47.117: INFO: Pod "pvc-snapshottable-tester-94lsg": Phase="Pending", Reason="", readiness=false. Elapsed: 37.406088ms
Sep 16 12:08:49.155: INFO: Pod "pvc-snapshottable-tester-94lsg": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.075537799s
STEP: Saw pod success
Sep 16 12:08:49.155: INFO: Pod "pvc-snapshottable-tester-94lsg" satisfied condition "Succeeded or Failed"
Sep 16 12:08:49.233: INFO: Pod pvc-snapshottable-tester-94lsg has the following logs: 
Sep 16 12:08:49.233: INFO: Deleting pod "pvc-snapshottable-tester-94lsg" in namespace "snapshotting-6175"
Sep 16 12:08:49.279: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-94lsg" to be fully deleted
Sep 16 12:08:49.323: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvqqj9] to have phase Bound
Sep 16 12:08:49.361: INFO: PersistentVolumeClaim test.csi.azure.comvqqj9 found and phase=Bound (37.379464ms)
STEP: [init] checking the claim
... skipping 102 lines ...
Sep 16 12:06:10.697: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-6443 PodName:pod-8799b44f-1a63-4e9f-87ce-f6204d40f40f ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:06:10.697: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:06:11.152: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-6443 PodName:pod-8799b44f-1a63-4e9f-87ce-f6204d40f40f ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:06:11.152: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:06:11.584: INFO: pod fsgroupchangepolicy-6443/pod-8799b44f-1a63-4e9f-87ce-f6204d40f40f exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 16 12:06 /mnt/volume1/subdir/file2, stderr: 
Sep 16 12:06:11.584: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 16 12:06 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 16 12:06:11.584: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc002047340, 0x70bd1d0, 0x19, 0xc00473c5f8, 0x4, 0xc0038ef800)
... skipping 71 lines ...
Sep 16 12:10:48.895: INFO: PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 found and phase=Bound (4m37.273208788s)
Sep 16 12:10:53.934: INFO: PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 found and phase=Bound (4m42.313023266s)
Sep 16 12:10:58.974: INFO: PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 found and phase=Bound (4m47.352268706s)
Sep 16 12:11:04.013: INFO: PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 found and phase=Bound (4m52.392088926s)
Sep 16 12:11:09.053: INFO: PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 found and phase=Bound (4m57.431722225s)
STEP: Deleting sc
Sep 16 12:11:14.095: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 not deleted by dynamic provisioner: PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-778f2ecc-b57a-4acd-a4b3-6f84184fe750 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, 0xc0030cc940)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc003e18d20, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc000e52000, 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(0xc003e18d20, 0x4c, 0xc004872c38, 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(0xc003e1ffc0, 0x37, 0xc000e984d0, 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(0xc004872dc0, 0x7904368, 0xc0044f3120, 0x1, 0x0, 0x0, 0x0, 0xc0044f3120)
	/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(0xc004872dc0, 0x7904368, 0xc0044f3120, 0x0, 0x0, 0x0, 0xc000480000)
	/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, 0xc0044f3100, 0x6323060, 0xc0044f3110, 0x0, 0x0, 0x0)
... skipping 142 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":14,"completed":0,"skipped":207,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (default fs)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:11:15.767: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 212 lines ...
Sep 16 12:11:16.696: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:11:16.737: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com7rkx5] to have phase Bound
Sep 16 12:11:16.783: INFO: PersistentVolumeClaim test.csi.azure.com7rkx5 found but phase is Pending instead of Bound.
Sep 16 12:11:18.824: INFO: PersistentVolumeClaim test.csi.azure.com7rkx5 found and phase=Bound (2.086375621s)
STEP: Creating pod exec-volume-test-dynamicpv-qk4q
STEP: Creating a pod to test exec-volume-test
Sep 16 12:11:18.942: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-qk4q" in namespace "volume-2435" to be "Succeeded or Failed"
Sep 16 12:11:18.981: INFO: Pod "exec-volume-test-dynamicpv-qk4q": Phase="Pending", Reason="", readiness=false. Elapsed: 39.108796ms
Sep 16 12:11:21.024: INFO: Pod "exec-volume-test-dynamicpv-qk4q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.082053013s
Sep 16 12:11:23.065: INFO: Pod "exec-volume-test-dynamicpv-qk4q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.122478039s
Sep 16 12:11:25.106: INFO: Pod "exec-volume-test-dynamicpv-qk4q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.163439524s
STEP: Saw pod success
Sep 16 12:11:25.106: INFO: Pod "exec-volume-test-dynamicpv-qk4q" satisfied condition "Succeeded or Failed"
Sep 16 12:11:25.145: INFO: Trying to get logs from node k8s-agentpool1-22559269-vmss000000 pod exec-volume-test-dynamicpv-qk4q container exec-container-dynamicpv-qk4q: <nil>
STEP: delete the pod
Sep 16 12:11:25.233: INFO: Waiting for pod exec-volume-test-dynamicpv-qk4q to disappear
Sep 16 12:11:25.272: INFO: Pod exec-volume-test-dynamicpv-qk4q no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-qk4q
Sep 16 12:11:25.272: INFO: Deleting pod "exec-volume-test-dynamicpv-qk4q" in namespace "volume-2435"
... 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":14,"completed":1,"skipped":816,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
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
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208
... skipping 30 lines ...
Sep 16 12:06:28.815: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-4104 PodName:pod-e62e3cd2-3191-4c2d-b398-4766c6afff73 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:06:28.815: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:06:29.163: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-4104 PodName:pod-e62e3cd2-3191-4c2d-b398-4766c6afff73 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:06:29.163: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:06:29.496: INFO: pod fsgroupchangepolicy-4104/pod-e62e3cd2-3191-4c2d-b398-4766c6afff73 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 16 12:06 /mnt/volume1/subdir/file2, stderr: 
Sep 16 12:06:29.496: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 16 12:06 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 16 12:06:29.496: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc0042da9a0, 0x70bd1d0, 0x19, 0xc003c91838, 0x4, 0xc003c64800)
... skipping 71 lines ...
Sep 16 12:11:06.644: INFO: PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 found and phase=Bound (4m37.10959914s)
Sep 16 12:11:11.681: INFO: PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 found and phase=Bound (4m42.146243331s)
Sep 16 12:11:16.717: INFO: PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 found and phase=Bound (4m47.182663901s)
Sep 16 12:11:21.756: INFO: PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 found and phase=Bound (4m52.22207977s)
Sep 16 12:11:26.793: INFO: PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 found and phase=Bound (4m57.258406781s)
STEP: Deleting sc
Sep 16 12:11:31.834: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 not deleted by dynamic provisioner: PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-139f8da0-4594-4481-94a2-4f43202ffec8 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, 0xc003792cc0)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc004360d20, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc0009eca00, 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(0xc004360d20, 0x4c, 0xc0012d2c38, 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(0xc00455e080, 0x37, 0xc002eacb20, 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(0xc0012d2dc0, 0x7904368, 0xc0037bd1e0, 0x1, 0x0, 0x0, 0x0, 0xc0037bd1e0)
	/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(0xc0012d2dc0, 0x7904368, 0xc0037bd1e0, 0x0, 0x0, 0x0, 0xc000480400)
	/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, 0xc0037bd1c0, 0x6323060, 0xc0037bd1d0, 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, volume contents ownership changed in first pod, new pod with same fsgroup applied to the volume contents","total":13,"completed":1,"skipped":302,"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 same fsgroup applied to the volume contents"]}

SSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
... skipping 102 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":14,"completed":2,"skipped":850,"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"]}

SSSSSSSSSSS
------------------------------
[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 16 12:11:53.356: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 31 lines ...
STEP: creating a claim
Sep 16 12:11:53.668: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 16 12:11:53.709: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvptpk] to have phase Bound
Sep 16 12:11:53.748: INFO: PersistentVolumeClaim test.csi.azure.comvptpk found but phase is Pending instead of Bound.
Sep 16 12:11:55.789: INFO: PersistentVolumeClaim test.csi.azure.comvptpk found and phase=Bound (2.079655095s)
STEP: [init] starting a pod to use the claim
Sep 16 12:11:55.908: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-2txnk" in namespace "snapshotting-2385" to be "Succeeded or Failed"
Sep 16 12:11:55.956: INFO: Pod "pvc-snapshottable-tester-2txnk": Phase="Pending", Reason="", readiness=false. Elapsed: 48.16605ms
Sep 16 12:11:57.996: INFO: Pod "pvc-snapshottable-tester-2txnk": Phase="Pending", Reason="", readiness=false. Elapsed: 2.088444839s
Sep 16 12:12:00.038: INFO: Pod "pvc-snapshottable-tester-2txnk": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.129738921s
STEP: Saw pod success
Sep 16 12:12:00.038: INFO: Pod "pvc-snapshottable-tester-2txnk" satisfied condition "Succeeded or Failed"
Sep 16 12:12:00.118: INFO: Pod pvc-snapshottable-tester-2txnk has the following logs: 
Sep 16 12:12:00.118: INFO: Deleting pod "pvc-snapshottable-tester-2txnk" in namespace "snapshotting-2385"
Sep 16 12:12:00.162: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-2txnk" to be fully deleted
Sep 16 12:12:00.201: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvptpk] to have phase Bound
Sep 16 12:12:00.240: INFO: PersistentVolumeClaim test.csi.azure.comvptpk found and phase=Bound (38.826277ms)
STEP: [init] checking the claim
... skipping 84 lines ...
Sep 16 12:07:03.835: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-852 PodName:pod-f5b08e33-21de-4a4d-b6eb-52fcbbd6470c ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:07:03.835: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:07:04.336: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-852 PodName:pod-f5b08e33-21de-4a4d-b6eb-52fcbbd6470c ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:07:04.337: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:07:04.646: INFO: pod fsgroupchangepolicy-852/pod-f5b08e33-21de-4a4d-b6eb-52fcbbd6470c exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 16 12:07 /mnt/volume1/subdir/file2, stderr: 
Sep 16 12:07:04.646: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 16 12:07 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 16 12:07:04.646: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc00459a420, 0x70bd1d0, 0x19, 0xc003729728, 0x4, 0xc0038e1400)
... skipping 71 lines ...
Sep 16 12:11:41.877: INFO: PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 found and phase=Bound (4m37.191374898s)
Sep 16 12:11:46.915: INFO: PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 found and phase=Bound (4m42.229970343s)
Sep 16 12:11:51.957: INFO: PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 found and phase=Bound (4m47.271164422s)
Sep 16 12:11:57.002: INFO: PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 found and phase=Bound (4m52.316372167s)
Sep 16 12:12:02.041: INFO: PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 found and phase=Bound (4m57.355957386s)
STEP: Deleting sc
Sep 16 12:12:07.082: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 not deleted by dynamic provisioner: PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-a8e5ab63-8f9c-47cf-9b07-54eefc6246d0 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, 0xc002de6bc0)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc004521e00, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc003930500, 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(0xc004521e00, 0x4c, 0xc002e3ec38, 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(0xc002d4cd00, 0x37, 0xc0036a63f0, 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(0xc002e3edc0, 0x7904368, 0xc00391a0a0, 0x1, 0x0, 0x0, 0x0, 0xc00391a0a0)
	/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(0xc002e3edc0, 0x7904368, 0xc00391a0a0, 0x0, 0x0, 0x0, 0xc003d10000)
	/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, 0xc00391a080, 0x6323060, 0xc00391a090, 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":18,"completed":1,"skipped":724,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 16 12:12:08.342: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 139 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":13,"completed":2,"skipped":509,"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 same fsgroup applied to the volume contents"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 16 12:12:13.323: INFO: Driver "test.csi.azure.com" does not support volume type "CSIInlineVolume" - skipping
... skipping 72 lines ...
Sep 16 12:07:51.876: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-3705 PodName:pod-8c40e719-5d84-41e8-9bf5-6b0bad1d8a84 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:07:51.876: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:07:52.240: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-3705 PodName:pod-8c40e719-5d84-41e8-9bf5-6b0bad1d8a84 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:07:52.240: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:07:52.653: INFO: pod fsgroupchangepolicy-3705/pod-8c40e719-5d84-41e8-9bf5-6b0bad1d8a84 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 16 12:07 /mnt/volume1/subdir/file2, stderr: 
Sep 16 12:07:52.653: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 16 12:07 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 16 12:07:52.653: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc00407b1e0, 0x70bd1d0, 0x19, 0xc0036fd5b8, 0x4, 0xc000808400)
... skipping 71 lines ...
Sep 16 12:12:29.893: INFO: PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 found and phase=Bound (4m37.200334371s)
Sep 16 12:12:34.932: INFO: PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 found and phase=Bound (4m42.239185633s)
Sep 16 12:12:39.972: INFO: PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 found and phase=Bound (4m47.279688569s)
Sep 16 12:12:45.011: INFO: PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 found and phase=Bound (4m52.318084598s)
Sep 16 12:12:50.050: INFO: PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 found and phase=Bound (4m57.357545551s)
STEP: Deleting sc
Sep 16 12:12:55.091: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 not deleted by dynamic provisioner: PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-2d09d992-aad7-40db-84bf-2902a5b0e529 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, 0xc000a20c40)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc002fe4550, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc0049e8a00, 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(0xc002fe4550, 0x4c, 0xc00338ac38, 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(0xc000a1e540, 0x37, 0xc0049a82d0, 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(0xc00338adc0, 0x7904368, 0xc0049c0370, 0x1, 0x0, 0x0, 0x0, 0xc0049c0370)
	/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(0xc00338adc0, 0x7904368, 0xc0049c0370, 0x0, 0x0, 0x0, 0xc000092800)
	/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, 0xc0049c0350, 0x6323060, 0xc0049c0360, 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":17,"completed":4,"skipped":810,"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"]}

SSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Inline-volume (ntfs)][Feature:Windows] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:12:56.318: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 61 lines ...
Sep 16 12:09:00.570: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-8001 PodName:pod-16ca45c2-b0b6-4f48-8508-21e5171e5fe2 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:09:00.570: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:09:01.162: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-8001 PodName:pod-16ca45c2-b0b6-4f48-8508-21e5171e5fe2 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:09:01.162: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:09:01.563: INFO: pod fsgroupchangepolicy-8001/pod-16ca45c2-b0b6-4f48-8508-21e5171e5fe2 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 16 12:09 /mnt/volume1/subdir/file2, stderr: 
Sep 16 12:09:01.563: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 16 12:09 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 16 12:09:01.564: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc003bd3760, 0x70bd1d0, 0x19, 0xc0025ae238, 0x4, 0xc003fa1000)
... skipping 71 lines ...
Sep 16 12:13:38.813: INFO: PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 found and phase=Bound (4m37.209188159s)
Sep 16 12:13:43.851: INFO: PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 found and phase=Bound (4m42.247545904s)
Sep 16 12:13:48.891: INFO: PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 found and phase=Bound (4m47.286758082s)
Sep 16 12:13:53.929: INFO: PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 found and phase=Bound (4m52.324775902s)
Sep 16 12:13:58.967: INFO: PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 found and phase=Bound (4m57.363323121s)
STEP: Deleting sc
Sep 16 12:14:04.008: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 not deleted by dynamic provisioner: PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-6f009033-3cd7-4057-bde3-120cfea9c430 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, 0xc003ebe400)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc002aac8c0, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc00177ea00, 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(0xc002aac8c0, 0x4c, 0xc004942c38, 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(0xc0037ab240, 0x37, 0xc0006ca770, 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(0xc004942dc0, 0x7904368, 0xc00414a150, 0x1, 0x0, 0x0, 0x0, 0xc00414a150)
	/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(0xc004942dc0, 0x7904368, 0xc00414a150, 0x0, 0x0, 0x0, 0xc000092800)
	/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, 0xc00414a110, 0x6323060, 0xc00414a140, 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, new pod fsgroup applied to volume contents","total":16,"completed":4,"skipped":883,"failed":1,"failures":["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"]}

SSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (delayed binding)] topology
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 16 12:14:05.232: INFO: Driver "test.csi.azure.com" does not support topology - skipping
... skipping 61 lines ...
Sep 16 12:12:19.627: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-1006 PodName:pod-857869e6-7c41-458f-9807-fc63a95448b9 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:12:19.627: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:12:20.010: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-1006 PodName:pod-857869e6-7c41-458f-9807-fc63a95448b9 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 16 12:12:20.010: INFO: >>> kubeConfig: /root/tmp844052287/kubeconfig/kubeconfig.southcentralus.json
Sep 16 12:12:20.481: INFO: pod fsgroupchangepolicy-1006/pod-857869e6-7c41-458f-9807-fc63a95448b9 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 16 12:12 /mnt/volume1/subdir/file2, stderr: 
Sep 16 12:12:20.481: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 16 12:12 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 16 12:12:20.481: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc0042da9a0, 0x70bd1d0, 0x19, 0xc004644398, 0x4, 0xc000093400)
... skipping 71 lines ...
Sep 16 12:16:57.677: INFO: PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae found and phase=Bound (4m37.155709249s)
Sep 16 12:17:02.716: INFO: PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae found and phase=Bound (4m42.194756088s)
Sep 16 12:17:07.755: INFO: PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae found and phase=Bound (4m47.233589034s)
Sep 16 12:17:12.791: INFO: PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae found and phase=Bound (4m52.269644685s)
Sep 16 12:17:17.826: INFO: PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae found and phase=Bound (4m57.304883954s)
STEP: Deleting sc
Sep 16 12:17:22.865: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-51474941-e974-4217-b10d-a7e3a7d083ae not deleted by dynamic provisioner: PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-51474941-e974-4217-b10d-a7e3a7d083ae 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, 0xc003443140)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc0032d6690, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc002c2a500, 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(0xc0032d6690, 0x4c, 0xc002a72c38, 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(0xc0020f6940, 0x37, 0xc00367e980, 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(0xc002a72dc0, 0x7904368, 0xc003b33bc0, 0x1, 0x0, 0x0, 0x0, 0xc003b33bc0)
	/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(0xc002a72dc0, 0x7904368, 0xc003b33bc0, 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, 0xc003b33b90, 0x6323060, 0xc003b33bb0, 0x0, 0x0, 0x0)
... skipping 134 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":13,"completed":2,"skipped":879,"failed":2,"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 same 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, volume contents ownership changed in first pod, new pod with same fsgroup skips ownership changes to the volume contents"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic 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 16 12:17:24.191: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 36 lines ...
Sep 16 12:17:24.279: 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] (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] (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] (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] (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] (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

[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

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

Ginkgo ran 1 suite in 12m21.562911736s
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.1
Platform: linux/amd64

Streaming logs below:
I0916 12:04:59.341013       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 gc/go1.17.1 (amd64-linux) e2e-test
I0916 12:04:59.341889       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0916 12:04:59.386490       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
I0916 12:04:59.386507       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0916 12:04:59.386512       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0916 12:04:59.386545       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0916 12:04:59.387586       1 azure_auth.go:234] Using AzurePublicCloud environment
I0916 12:04:59.388450       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0916 12:04:59.388625       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.1
Platform: linux/amd64

Streaming logs below:
I0916 12:05:00.337174       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 gc/go1.17.1 (amd64-linux) e2e-test
I0916 12:05:00.338449       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0916 12:05:00.367895       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
I0916 12:05:00.367925       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0916 12:05:00.367932       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0916 12:05:00.367963       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0916 12:05:00.373742       1 azure_auth.go:234] Using AzurePublicCloud environment
I0916 12:05:00.373785       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0916 12:05:00.373808       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 101 lines ...
Go Version: go1.17.1
Platform: linux/amd64

Streaming logs below:
I0916 12:04:43.211167       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 gc/go1.17.1 (amd64-linux) e2e-test
I0916 12:04:43.212198       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0916 12:04:43.241824       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
I0916 12:04:43.241859       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0916 12:04:43.241866       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0916 12:04:43.241888       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0916 12:04:43.242908       1 azure_auth.go:234] Using AzurePublicCloud environment
I0916 12:04:43.242947       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0916 12:04:43.242970       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 68 lines ...
Go Version: go1.17.1
Platform: linux/amd64

Streaming logs below:
I0916 12:04:51.730830       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 gc/go1.17.1 (amd64-linux) e2e-test
I0916 12:04:51.733087       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0916 12:04:51.759786       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
I0916 12:04:51.759806       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0916 12:04:51.759811       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0916 12:04:51.759885       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0916 12:04:51.760412       1 azure_auth.go:234] Using AzurePublicCloud environment
I0916 12:04:51.760445       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0916 12:04:51.760467       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 651 lines ...
Go Version: go1.17.1
Platform: linux/amd64

Streaming logs below:
I0916 12:04:51.763697       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-5c798c110cb3a820e89f51e394bd67e540cbddf0 gc/go1.17.1 (amd64-linux) e2e-test
I0916 12:04:51.764656       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0916 12:04:51.783327       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
I0916 12:04:51.783346       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0916 12:04:51.783352       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0916 12:04:51.783369       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0916 12:04:51.784385       1 azure_auth.go:234] Using AzurePublicCloud environment
I0916 12:04:51.784533       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0916 12:04:51.784637       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 921 lines ...
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 7.621632e+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/16 12:18:16 process.go:155: Step 'make e2e-test' finished in 21m53.164169263s
2021/09/16 12:18:16 aksengine_helpers.go:425: downloading /root/tmp844052287/log-dump.sh from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh
2021/09/16 12:18:16 util.go:68: curl https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh
2021/09/16 12:18:16 process.go:153: Running: chmod +x /root/tmp844052287/log-dump.sh
2021/09/16 12:18:16 process.go:155: Step 'chmod +x /root/tmp844052287/log-dump.sh' finished in 1.221261ms
2021/09/16 12:18:16 aksengine_helpers.go:425: downloading /root/tmp844052287/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/16 12:18:44 process.go:155: Step 'bash -c /root/tmp844052287/win-ci-logs-collector.sh kubetest-4oi7mnes.southcentralus.cloudapp.azure.com /root/tmp844052287 /root/.ssh/id_rsa' finished in 4.754466ms
2021/09/16 12:18:44 aksengine.go:1141: Deleting resource group: kubetest-4oi7mnes.
2021/09/16 12:26:48 process.go:96: Saved XML output to /logs/artifacts/junit_runner.xml.
2021/09/16 12:26:48 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
2021/09/16 12:26:48 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 221.847157ms
2021/09/16 12:26:48 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
ca49711cf98c
... skipping 4 lines ...