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-15 13:36
Elapsed35m15s
Revisiona97a4dfe3a750f3f07b31336219000590b3d88c7
Refs 759
job-versionv1.23.0-alpha.2.15+73d51a21dbe750
kubetest-version
revisionv1.23.0-alpha.2.15+73d51a21dbe750

Test Failures


kubetest Test 23m6s

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  90709      0 --:--:-- --:--:-- --:--:-- 90709
Downloading https://get.helm.sh/helm-v3.6.3-linux-amd64.tar.gz
Verifying checksum... Done.
Preparing to install helm into /usr/local/bin
helm installed into /usr/local/bin/helm
docker pull k8sprow.azurecr.io/azurefile-csi:e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 || make container-all push-manifest
Error response from daemon: manifest for k8sprow.azurecr.io/azurefile-csi:e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 not found: manifest unknown: manifest tagged by "e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5" 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-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.gitCommit=75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 -X sigs.k8s.io/azurefile-csi-driver/pkg/azurefile.buildDate=2021-09-15T13:39:59Z -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 1726 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 491 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 8 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 182 lines ...
Sep 15 13:50:32.453: INFO: PersistentVolumeClaim test.csi.azure.comvvvcx found but phase is Pending instead of Bound.
Sep 15 13:50:34.482: INFO: PersistentVolumeClaim test.csi.azure.comvvvcx found but phase is Pending instead of Bound.
Sep 15 13:50:36.511: INFO: PersistentVolumeClaim test.csi.azure.comvvvcx found but phase is Pending instead of Bound.
Sep 15 13:50:38.540: INFO: PersistentVolumeClaim test.csi.azure.comvvvcx found but phase is Pending instead of Bound.
Sep 15 13:50:40.574: INFO: PersistentVolumeClaim test.csi.azure.comvvvcx found and phase=Bound (54.805213702s)
STEP: [init] starting a pod to use the claim
Sep 15 13:50:40.657: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-rnqd2" in namespace "snapshotting-5942" to be "Succeeded or Failed"
Sep 15 13:50:40.685: INFO: Pod "pvc-snapshottable-tester-rnqd2": Phase="Pending", Reason="", readiness=false. Elapsed: 27.247484ms
Sep 15 13:50:42.714: INFO: Pod "pvc-snapshottable-tester-rnqd2": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056811628s
Sep 15 13:50:44.743: INFO: Pod "pvc-snapshottable-tester-rnqd2": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.085540629s
STEP: Saw pod success
Sep 15 13:50:44.743: INFO: Pod "pvc-snapshottable-tester-rnqd2" satisfied condition "Succeeded or Failed"
Sep 15 13:50:45.401: INFO: Pod pvc-snapshottable-tester-rnqd2 has the following logs: 
Sep 15 13:50:45.401: INFO: Deleting pod "pvc-snapshottable-tester-rnqd2" in namespace "snapshotting-5942"
Sep 15 13:50:45.440: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-rnqd2" to be fully deleted
Sep 15 13:50:45.468: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comvvvcx] to have phase Bound
Sep 15 13:50:45.497: INFO: PersistentVolumeClaim test.csi.azure.comvvvcx found and phase=Bound (28.739133ms)
STEP: [init] checking the claim
... skipping 104 lines ...
Sep 15 13:50:32.391: INFO: PersistentVolumeClaim test.csi.azure.compr9d7 found but phase is Pending instead of Bound.
Sep 15 13:50:34.419: INFO: PersistentVolumeClaim test.csi.azure.compr9d7 found but phase is Pending instead of Bound.
Sep 15 13:50:36.448: INFO: PersistentVolumeClaim test.csi.azure.compr9d7 found but phase is Pending instead of Bound.
Sep 15 13:50:38.480: INFO: PersistentVolumeClaim test.csi.azure.compr9d7 found but phase is Pending instead of Bound.
Sep 15 13:50:40.508: INFO: PersistentVolumeClaim test.csi.azure.compr9d7 found and phase=Bound (54.810143854s)
STEP: [init] starting a pod to use the claim
Sep 15 13:50:40.592: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-h9hhf" in namespace "snapshotting-7434" to be "Succeeded or Failed"
Sep 15 13:50:40.620: INFO: Pod "pvc-snapshottable-tester-h9hhf": Phase="Pending", Reason="", readiness=false. Elapsed: 27.386415ms
Sep 15 13:50:42.648: INFO: Pod "pvc-snapshottable-tester-h9hhf": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056017486s
Sep 15 13:50:44.678: INFO: Pod "pvc-snapshottable-tester-h9hhf": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.085427716s
STEP: Saw pod success
Sep 15 13:50:44.678: INFO: Pod "pvc-snapshottable-tester-h9hhf" satisfied condition "Succeeded or Failed"
Sep 15 13:50:45.601: INFO: Pod pvc-snapshottable-tester-h9hhf has the following logs: 
Sep 15 13:50:45.601: INFO: Deleting pod "pvc-snapshottable-tester-h9hhf" in namespace "snapshotting-7434"
Sep 15 13:50:45.633: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-h9hhf" to be fully deleted
Sep 15 13:50:45.661: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.compr9d7] to have phase Bound
Sep 15 13:50:45.689: INFO: PersistentVolumeClaim test.csi.azure.compr9d7 found and phase=Bound (27.743339ms)
STEP: [init] checking the claim
... skipping 150 lines ...
Sep 15 13:50:34.192: INFO: PersistentVolumeClaim test.csi.azure.com56d4q found but phase is Pending instead of Bound.
Sep 15 13:50:36.221: INFO: PersistentVolumeClaim test.csi.azure.com56d4q found but phase is Pending instead of Bound.
Sep 15 13:50:38.249: INFO: PersistentVolumeClaim test.csi.azure.com56d4q found but phase is Pending instead of Bound.
Sep 15 13:50:40.277: INFO: PersistentVolumeClaim test.csi.azure.com56d4q found and phase=Bound (54.814498052s)
STEP: Creating pod pod-subpath-test-dynamicpv-6z29
STEP: Creating a pod to test subpath
Sep 15 13:50:40.362: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-6z29" in namespace "provisioning-8225" to be "Succeeded or Failed"
Sep 15 13:50:40.389: INFO: Pod "pod-subpath-test-dynamicpv-6z29": Phase="Pending", Reason="", readiness=false. Elapsed: 27.485978ms
Sep 15 13:50:42.417: INFO: Pod "pod-subpath-test-dynamicpv-6z29": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055654602s
Sep 15 13:50:44.446: INFO: Pod "pod-subpath-test-dynamicpv-6z29": Phase="Pending", Reason="", readiness=false. Elapsed: 4.083754257s
Sep 15 13:50:46.474: INFO: Pod "pod-subpath-test-dynamicpv-6z29": Phase="Pending", Reason="", readiness=false. Elapsed: 6.111898751s
Sep 15 13:50:48.503: INFO: Pod "pod-subpath-test-dynamicpv-6z29": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8.141079943s
STEP: Saw pod success
Sep 15 13:50:48.503: INFO: Pod "pod-subpath-test-dynamicpv-6z29" satisfied condition "Succeeded or Failed"
Sep 15 13:50:48.530: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000001 pod pod-subpath-test-dynamicpv-6z29 container test-container-volume-dynamicpv-6z29: <nil>
STEP: delete the pod
Sep 15 13:50:48.680: INFO: Waiting for pod pod-subpath-test-dynamicpv-6z29 to disappear
Sep 15 13:50:48.707: INFO: Pod pod-subpath-test-dynamicpv-6z29 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-6z29
Sep 15 13:50:48.707: INFO: Deleting pod "pod-subpath-test-dynamicpv-6z29" in namespace "provisioning-8225"
... 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":17,"completed":1,"skipped":105,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:50:54.013: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 128 lines ...
Sep 15 13:50:34.537: INFO: PersistentVolumeClaim test.csi.azure.comnv8sm found but phase is Pending instead of Bound.
Sep 15 13:50:36.565: INFO: PersistentVolumeClaim test.csi.azure.comnv8sm found but phase is Pending instead of Bound.
Sep 15 13:50:38.593: INFO: PersistentVolumeClaim test.csi.azure.comnv8sm found but phase is Pending instead of Bound.
Sep 15 13:50:40.620: INFO: PersistentVolumeClaim test.csi.azure.comnv8sm found and phase=Bound (54.793382829s)
STEP: Creating pod pod-subpath-test-dynamicpv-qjt9
STEP: Creating a pod to test subpath
Sep 15 13:50:40.704: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-qjt9" in namespace "provisioning-6159" to be "Succeeded or Failed"
Sep 15 13:50:40.731: INFO: Pod "pod-subpath-test-dynamicpv-qjt9": Phase="Pending", Reason="", readiness=false. Elapsed: 27.108349ms
Sep 15 13:50:42.759: INFO: Pod "pod-subpath-test-dynamicpv-qjt9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055136934s
Sep 15 13:50:44.787: INFO: Pod "pod-subpath-test-dynamicpv-qjt9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.083638231s
Sep 15 13:50:46.816: INFO: Pod "pod-subpath-test-dynamicpv-qjt9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.11253921s
Sep 15 13:50:48.845: INFO: Pod "pod-subpath-test-dynamicpv-qjt9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8.141274423s
STEP: Saw pod success
Sep 15 13:50:48.845: INFO: Pod "pod-subpath-test-dynamicpv-qjt9" satisfied condition "Succeeded or Failed"
Sep 15 13:50:48.872: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000001 pod pod-subpath-test-dynamicpv-qjt9 container test-container-subpath-dynamicpv-qjt9: <nil>
STEP: delete the pod
Sep 15 13:50:48.935: INFO: Waiting for pod pod-subpath-test-dynamicpv-qjt9 to disappear
Sep 15 13:50:48.962: INFO: Pod pod-subpath-test-dynamicpv-qjt9 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-qjt9
Sep 15 13:50:48.963: INFO: Deleting pod "pod-subpath-test-dynamicpv-qjt9" in namespace "provisioning-6159"
... 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":13,"completed":1,"skipped":177,"failed":0}

S
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volume-expand
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 15 13:50:54.216: INFO: Driver "test.csi.azure.com" does not support block volume mode - skipping
... skipping 121 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":1,"skipped":375,"failed":0}

SSSSSSSSSSSSS
------------------------------
[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 15 13:51:02.772: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 193 lines ...
Sep 15 13:50:51.299: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:50:51.330: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comtwmdk] to have phase Bound
Sep 15 13:50:51.357: INFO: PersistentVolumeClaim test.csi.azure.comtwmdk found but phase is Pending instead of Bound.
Sep 15 13:50:53.385: INFO: PersistentVolumeClaim test.csi.azure.comtwmdk found and phase=Bound (2.054994504s)
STEP: Creating pod pod-subpath-test-dynamicpv-xbnd
STEP: Creating a pod to test subpath
Sep 15 13:50:53.474: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-xbnd" in namespace "provisioning-5316" to be "Succeeded or Failed"
Sep 15 13:50:53.502: INFO: Pod "pod-subpath-test-dynamicpv-xbnd": Phase="Pending", Reason="", readiness=false. Elapsed: 27.431142ms
Sep 15 13:50:55.530: INFO: Pod "pod-subpath-test-dynamicpv-xbnd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055487232s
Sep 15 13:50:57.558: INFO: Pod "pod-subpath-test-dynamicpv-xbnd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.083812821s
Sep 15 13:50:59.588: INFO: Pod "pod-subpath-test-dynamicpv-xbnd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.113498365s
Sep 15 13:51:01.616: INFO: Pod "pod-subpath-test-dynamicpv-xbnd": Phase="Succeeded", Reason="", readiness=false. Elapsed: 8.142171926s
STEP: Saw pod success
Sep 15 13:51:01.616: INFO: Pod "pod-subpath-test-dynamicpv-xbnd" satisfied condition "Succeeded or Failed"
Sep 15 13:51:01.644: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000000 pod pod-subpath-test-dynamicpv-xbnd container test-container-subpath-dynamicpv-xbnd: <nil>
STEP: delete the pod
Sep 15 13:51:01.710: INFO: Waiting for pod pod-subpath-test-dynamicpv-xbnd to disappear
Sep 15 13:51:01.737: INFO: Pod pod-subpath-test-dynamicpv-xbnd no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-xbnd
Sep 15 13:51:01.737: INFO: Deleting pod "pod-subpath-test-dynamicpv-xbnd" in namespace "provisioning-5316"
... 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":18,"completed":1,"skipped":233,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 15 13:51:07.065: INFO: Driver "test.csi.azure.com" does not provide raw block - skipping
... skipping 236 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":13,"completed":2,"skipped":185,"failed":0}

SSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes 
  should store data
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:159
... skipping 68 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":12,"completed":1,"skipped":502,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:51:12.431: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 63 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":17,"completed":2,"skipped":457,"failed":0}
[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 15 13:51:12.600: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
[AfterEach] [Testpattern: Pre-provisioned PV (ext4)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:186

... skipping 83 lines ...
Sep 15 13:50:34.581: INFO: PersistentVolumeClaim test.csi.azure.com7786n found but phase is Pending instead of Bound.
Sep 15 13:50:36.612: INFO: PersistentVolumeClaim test.csi.azure.com7786n found but phase is Pending instead of Bound.
Sep 15 13:50:38.644: INFO: PersistentVolumeClaim test.csi.azure.com7786n found but phase is Pending instead of Bound.
Sep 15 13:50:40.675: INFO: PersistentVolumeClaim test.csi.azure.com7786n found and phase=Bound (54.895460421s)
STEP: Expanding non-expandable pvc
Sep 15 13:50:40.739: INFO: currentPvcSize {{5368709120 0} {<nil>} 5Gi BinarySI}, newSize {{6442450944 0} {<nil>}  BinarySI}
Sep 15 13:50:40.802: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:42.865: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:44.866: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:46.867: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:48.865: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:50.866: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:52.867: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:54.866: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:56.865: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:50:58.866: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:00.865: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:02.868: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:04.867: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:06.866: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:08.867: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:10.867: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
Sep 15 13:51:10.930: INFO: Error updating pvc test.csi.azure.com7786n: persistentvolumeclaims "test.csi.azure.com7786n" is forbidden: only dynamically provisioned pvc can be resized and the storageclass that provisions the pvc must support resize
STEP: Deleting pvc
Sep 15 13:51:10.930: INFO: Deleting PersistentVolumeClaim "test.csi.azure.com7786n"
Sep 15 13:51:10.962: INFO: Waiting up to 5m0s for PersistentVolume pvc-565c871f-7891-4b54-bd8a-af4b98607f46 to get deleted
Sep 15 13:51:10.993: INFO: PersistentVolume pvc-565c871f-7891-4b54-bd8a-af4b98607f46 found and phase=Released (30.703263ms)
Sep 15 13:51:16.026: INFO: PersistentVolume pvc-565c871f-7891-4b54-bd8a-af4b98607f46 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":21,"completed":1,"skipped":119,"failed":0}

SSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-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 36 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":14,"completed":1,"skipped":308,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] subPath 
  should support existing directory
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:205
... skipping 15 lines ...
Sep 15 13:51:12.963: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:51:12.992: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comg7cvg] to have phase Bound
Sep 15 13:51:13.020: INFO: PersistentVolumeClaim test.csi.azure.comg7cvg found but phase is Pending instead of Bound.
Sep 15 13:51:15.048: INFO: PersistentVolumeClaim test.csi.azure.comg7cvg found and phase=Bound (2.055858656s)
STEP: Creating pod pod-subpath-test-dynamicpv-pghn
STEP: Creating a pod to test subpath
Sep 15 13:51:15.134: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-pghn" in namespace "provisioning-6430" to be "Succeeded or Failed"
Sep 15 13:51:15.161: INFO: Pod "pod-subpath-test-dynamicpv-pghn": Phase="Pending", Reason="", readiness=false. Elapsed: 27.242801ms
Sep 15 13:51:17.190: INFO: Pod "pod-subpath-test-dynamicpv-pghn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056125208s
Sep 15 13:51:19.220: INFO: Pod "pod-subpath-test-dynamicpv-pghn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.086002855s
STEP: Saw pod success
Sep 15 13:51:19.220: INFO: Pod "pod-subpath-test-dynamicpv-pghn" satisfied condition "Succeeded or Failed"
Sep 15 13:51:19.247: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000000 pod pod-subpath-test-dynamicpv-pghn container test-container-volume-dynamicpv-pghn: <nil>
STEP: delete the pod
Sep 15 13:51:19.319: INFO: Waiting for pod pod-subpath-test-dynamicpv-pghn to disappear
Sep 15 13:51:19.346: INFO: Pod pod-subpath-test-dynamicpv-pghn no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-pghn
Sep 15 13:51:19.346: INFO: Deleting pod "pod-subpath-test-dynamicpv-pghn" in namespace "provisioning-6430"
... 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":3,"skipped":679,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (immediate binding)] topology
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 15 13:51:24.653: INFO: Driver "test.csi.azure.com" does not support topology - skipping
... skipping 57 lines ...
Sep 15 13:51:11.415: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:51:11.444: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comg9wxt] to have phase Bound
Sep 15 13:51:11.472: INFO: PersistentVolumeClaim test.csi.azure.comg9wxt found but phase is Pending instead of Bound.
Sep 15 13:51:13.500: INFO: PersistentVolumeClaim test.csi.azure.comg9wxt found and phase=Bound (2.055442123s)
STEP: Creating pod pod-subpath-test-dynamicpv-s6rs
STEP: Creating a pod to test atomic-volume-subpath
Sep 15 13:51:13.589: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-s6rs" in namespace "provisioning-9747" to be "Succeeded or Failed"
Sep 15 13:51:13.618: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Pending", Reason="", readiness=false. Elapsed: 29.406978ms
Sep 15 13:51:15.647: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Pending", Reason="", readiness=false. Elapsed: 2.05857414s
Sep 15 13:51:17.675: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 4.085913068s
Sep 15 13:51:19.703: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 6.114015428s
Sep 15 13:51:21.732: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 8.143135381s
Sep 15 13:51:23.761: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 10.172425011s
... skipping 2 lines ...
Sep 15 13:51:29.848: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 16.25941811s
Sep 15 13:51:31.877: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 18.287943903s
Sep 15 13:51:33.906: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 20.316992081s
Sep 15 13:51:35.934: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Running", Reason="", readiness=true. Elapsed: 22.345491651s
Sep 15 13:51:37.964: INFO: Pod "pod-subpath-test-dynamicpv-s6rs": Phase="Succeeded", Reason="", readiness=false. Elapsed: 24.375181913s
STEP: Saw pod success
Sep 15 13:51:37.964: INFO: Pod "pod-subpath-test-dynamicpv-s6rs" satisfied condition "Succeeded or Failed"
Sep 15 13:51:37.992: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000001 pod pod-subpath-test-dynamicpv-s6rs container test-container-subpath-dynamicpv-s6rs: <nil>
STEP: delete the pod
Sep 15 13:51:38.057: INFO: Waiting for pod pod-subpath-test-dynamicpv-s6rs to disappear
Sep 15 13:51:38.084: INFO: Pod pod-subpath-test-dynamicpv-s6rs no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-s6rs
Sep 15 13:51:38.084: INFO: Deleting pod "pod-subpath-test-dynamicpv-s6rs" in namespace "provisioning-9747"
... 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":13,"completed":3,"skipped":191,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] volumes 
  should allow exec of files on the volume
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:196
... skipping 15 lines ...
Sep 15 13:51:43.594: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:51:43.623: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comp7vnt] to have phase Bound
Sep 15 13:51:43.651: INFO: PersistentVolumeClaim test.csi.azure.comp7vnt found but phase is Pending instead of Bound.
Sep 15 13:51:45.679: INFO: PersistentVolumeClaim test.csi.azure.comp7vnt found and phase=Bound (2.055484477s)
STEP: Creating pod exec-volume-test-dynamicpv-5h22
STEP: Creating a pod to test exec-volume-test
Sep 15 13:51:45.764: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-5h22" in namespace "volume-6130" to be "Succeeded or Failed"
Sep 15 13:51:45.791: INFO: Pod "exec-volume-test-dynamicpv-5h22": Phase="Pending", Reason="", readiness=false. Elapsed: 27.33317ms
Sep 15 13:51:47.820: INFO: Pod "exec-volume-test-dynamicpv-5h22": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056600746s
Sep 15 13:51:49.849: INFO: Pod "exec-volume-test-dynamicpv-5h22": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.085672762s
STEP: Saw pod success
Sep 15 13:51:49.849: INFO: Pod "exec-volume-test-dynamicpv-5h22" satisfied condition "Succeeded or Failed"
Sep 15 13:51:49.877: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000000 pod exec-volume-test-dynamicpv-5h22 container exec-container-dynamicpv-5h22: <nil>
STEP: delete the pod
Sep 15 13:51:49.942: INFO: Waiting for pod exec-volume-test-dynamicpv-5h22 to disappear
Sep 15 13:51:49.970: INFO: Pod exec-volume-test-dynamicpv-5h22 no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-5h22
Sep 15 13:51:49.970: INFO: Deleting pod "exec-volume-test-dynamicpv-5h22" in namespace "volume-6130"
... 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":13,"completed":4,"skipped":289,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (immediate-binding)] ephemeral 
  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
... skipping 36 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":12,"completed":2,"skipped":614,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ext3)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 15 13:51:55.810: INFO: Driver test.csi.azure.com doesn't support ext3 -- skipping
... skipping 58 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":21,"completed":2,"skipped":133,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:51:58.653: INFO: Driver test.csi.azure.com doesn't support Block -- skipping
... skipping 73 lines ...
STEP: creating a claim
Sep 15 13:51:55.995: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:51:56.025: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comzpzk8] to have phase Bound
Sep 15 13:51:56.052: INFO: PersistentVolumeClaim test.csi.azure.comzpzk8 found but phase is Pending instead of Bound.
Sep 15 13:51:58.081: INFO: PersistentVolumeClaim test.csi.azure.comzpzk8 found and phase=Bound (2.056167316s)
STEP: [init] starting a pod to use the claim
Sep 15 13:51:58.167: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-bf6kx" in namespace "snapshotting-968" to be "Succeeded or Failed"
Sep 15 13:51:58.194: INFO: Pod "pvc-snapshottable-tester-bf6kx": Phase="Pending", Reason="", readiness=false. Elapsed: 27.699461ms
Sep 15 13:52:00.223: INFO: Pod "pvc-snapshottable-tester-bf6kx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.055971902s
STEP: Saw pod success
Sep 15 13:52:00.223: INFO: Pod "pvc-snapshottable-tester-bf6kx" satisfied condition "Succeeded or Failed"
Sep 15 13:52:00.279: INFO: Pod pvc-snapshottable-tester-bf6kx has the following logs: 
Sep 15 13:52:00.279: INFO: Deleting pod "pvc-snapshottable-tester-bf6kx" in namespace "snapshotting-968"
Sep 15 13:52:00.313: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-bf6kx" to be fully deleted
Sep 15 13:52:00.346: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comzpzk8] to have phase Bound
Sep 15 13:52:00.373: INFO: PersistentVolumeClaim test.csi.azure.comzpzk8 found and phase=Bound (27.023975ms)
STEP: [init] checking the claim
... skipping 146 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":18,"completed":2,"skipped":705,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:52:23.760: INFO: Driver "test.csi.azure.com" does not support volume type "InlineVolume" - skipping
... skipping 80 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":18,"completed":3,"skipped":815,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
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 45 lines ...
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/external/external.go:174
  [Testpattern: Generic Ephemeral-volume (default fs) (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":21,"completed":3,"skipped":451,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:53:14.855: INFO: Driver "test.csi.azure.com" does not support block volume mode - skipping
... skipping 172 lines ...
Sep 15 13:53:02.886: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:53:02.914: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com8vfjj] to have phase Bound
Sep 15 13:53:02.942: INFO: PersistentVolumeClaim test.csi.azure.com8vfjj found but phase is Pending instead of Bound.
Sep 15 13:53:04.970: INFO: PersistentVolumeClaim test.csi.azure.com8vfjj found and phase=Bound (2.056191452s)
STEP: Creating pod pod-subpath-test-dynamicpv-lcl6
STEP: Creating a pod to test subpath
Sep 15 13:53:05.055: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-lcl6" in namespace "provisioning-1726" to be "Succeeded or Failed"
Sep 15 13:53:05.082: INFO: Pod "pod-subpath-test-dynamicpv-lcl6": Phase="Pending", Reason="", readiness=false. Elapsed: 27.19064ms
Sep 15 13:53:07.110: INFO: Pod "pod-subpath-test-dynamicpv-lcl6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.055208434s
Sep 15 13:53:09.147: INFO: Pod "pod-subpath-test-dynamicpv-lcl6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.09212533s
STEP: Saw pod success
Sep 15 13:53:09.147: INFO: Pod "pod-subpath-test-dynamicpv-lcl6" satisfied condition "Succeeded or Failed"
Sep 15 13:53:09.175: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000001 pod pod-subpath-test-dynamicpv-lcl6 container test-container-subpath-dynamicpv-lcl6: <nil>
STEP: delete the pod
Sep 15 13:53:09.242: INFO: Waiting for pod pod-subpath-test-dynamicpv-lcl6 to disappear
Sep 15 13:53:09.269: INFO: Pod pod-subpath-test-dynamicpv-lcl6 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-lcl6
Sep 15 13:53:09.269: INFO: Deleting pod "pod-subpath-test-dynamicpv-lcl6" in namespace "provisioning-1726"
STEP: Creating pod pod-subpath-test-dynamicpv-lcl6
STEP: Creating a pod to test subpath
Sep 15 13:53:09.325: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-lcl6" in namespace "provisioning-1726" to be "Succeeded or Failed"
Sep 15 13:53:09.356: INFO: Pod "pod-subpath-test-dynamicpv-lcl6": Phase="Pending", Reason="", readiness=false. Elapsed: 30.619658ms
Sep 15 13:53:11.386: INFO: Pod "pod-subpath-test-dynamicpv-lcl6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.060304747s
STEP: Saw pod success
Sep 15 13:53:11.386: INFO: Pod "pod-subpath-test-dynamicpv-lcl6" satisfied condition "Succeeded or Failed"
Sep 15 13:53:11.414: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000001 pod pod-subpath-test-dynamicpv-lcl6 container test-container-subpath-dynamicpv-lcl6: <nil>
STEP: delete the pod
Sep 15 13:53:11.476: INFO: Waiting for pod pod-subpath-test-dynamicpv-lcl6 to disappear
Sep 15 13:53:11.506: INFO: Pod pod-subpath-test-dynamicpv-lcl6 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-lcl6
Sep 15 13:53:11.506: INFO: Deleting pod "pod-subpath-test-dynamicpv-lcl6" in namespace "provisioning-1726"
... 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":18,"completed":4,"skipped":840,"failed":0}

S
------------------------------
[BeforeEach] [Testpattern: Dynamic Snapshot (delete 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: Dynamic Snapshot (delete policy)] snapshottable[Feature:VolumeSnapshotDataSource]
... skipping 10 lines ...
STEP: creating a claim
Sep 15 13:53:16.927: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:53:16.956: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comdvnch] to have phase Bound
Sep 15 13:53:16.984: INFO: PersistentVolumeClaim test.csi.azure.comdvnch found but phase is Pending instead of Bound.
Sep 15 13:53:19.012: INFO: PersistentVolumeClaim test.csi.azure.comdvnch found and phase=Bound (2.05527173s)
STEP: [init] starting a pod to use the claim
Sep 15 13:53:19.096: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-wbqmm" in namespace "snapshotting-6933" to be "Succeeded or Failed"
Sep 15 13:53:19.124: INFO: Pod "pvc-snapshottable-tester-wbqmm": Phase="Pending", Reason="", readiness=false. Elapsed: 27.674834ms
Sep 15 13:53:21.152: INFO: Pod "pvc-snapshottable-tester-wbqmm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 2.056355044s
STEP: Saw pod success
Sep 15 13:53:21.153: INFO: Pod "pvc-snapshottable-tester-wbqmm" satisfied condition "Succeeded or Failed"
Sep 15 13:53:21.209: INFO: Pod pvc-snapshottable-tester-wbqmm has the following logs: 
Sep 15 13:53:21.209: INFO: Deleting pod "pvc-snapshottable-tester-wbqmm" in namespace "snapshotting-6933"
Sep 15 13:53:21.242: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-wbqmm" to be fully deleted
Sep 15 13:53:21.270: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.comdvnch] to have phase Bound
Sep 15 13:53:21.297: INFO: PersistentVolumeClaim test.csi.azure.comdvnch found and phase=Bound (27.255729ms)
STEP: [init] checking the claim
... skipping 85 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":18,"completed":5,"skipped":861,"failed":0}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
Sep 15 13:53:40.552: INFO: Running AfterSuite actions on all nodes
Sep 15 13:53:40.552: INFO: Running Cleanup Action: k8s.io/kubernetes/test/e2e/storage.glob..func17.2
Sep 15 13:53:40.552: INFO: Running Cleanup Action: k8s.io/kubernetes/test/e2e/storage.glob..func8.2
... skipping 40 lines ...
Sep 15 13:51:29.037: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-6875 PodName:pod-83453461-7570-49d2-b3cd-f1af0d2f5175 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:51:29.037: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:51:29.361: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-6875 PodName:pod-83453461-7570-49d2-b3cd-f1af0d2f5175 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:51:29.362: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:51:29.640: INFO: pod fsgroupchangepolicy-6875/pod-83453461-7570-49d2-b3cd-f1af0d2f5175 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 15 13:51 /mnt/volume1/subdir/file2, stderr: 
Sep 15 13:51:29.640: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 15 13:51 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 15 13:51:29.641: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc002eefce0, 0x70bd1d0, 0x19, 0xc00324f148, 0x4, 0xc0024e7400)
... skipping 71 lines ...
Sep 15 13:56:06.369: INFO: PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec found and phase=Bound (4m36.695827916s)
Sep 15 13:56:11.397: INFO: PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec found and phase=Bound (4m41.724115324s)
Sep 15 13:56:16.426: INFO: PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec found and phase=Bound (4m46.752893082s)
Sep 15 13:56:21.455: INFO: PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec found and phase=Bound (4m51.781843871s)
Sep 15 13:56:26.484: INFO: PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec found and phase=Bound (4m56.810631792s)
STEP: Deleting sc
Sep 15 13:56:31.515: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec not deleted by dynamic provisioner: PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-d6eeaff7-66fa-4317-a61a-3ff35cd02eec 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, 0xc00377c440)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc000138870, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc0039c0a00, 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(0xc000138870, 0x4c, 0xc002dacc38, 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(0xc0024a3d00, 0x37, 0xc003740f30, 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(0xc002dacdc0, 0x7904368, 0xc0037583e0, 0x1, 0x0, 0x0, 0x0, 0xc0037583e0)
	/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(0xc002dacdc0, 0x7904368, 0xc0037583e0, 0x0, 0x0, 0x0, 0xc000093400)
	/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, 0xc0037583c0, 0x6323060, 0xc0037583d0, 0x0, 0x0, 0x0)
... skipping 140 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents","total":14,"completed":1,"skipped":366,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 82 lines ...
Sep 15 13:52:00.866: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-6562 PodName:pod-a1b1bf9c-7799-4110-8ef0-b549526ed284 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:52:00.866: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:52:01.178: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-6562 PodName:pod-a1b1bf9c-7799-4110-8ef0-b549526ed284 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:52:01.179: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:52:01.560: INFO: pod fsgroupchangepolicy-6562/pod-a1b1bf9c-7799-4110-8ef0-b549526ed284 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 15 13:52 /mnt/volume1/subdir/file2, stderr: 
Sep 15 13:52:01.560: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 15 13:52 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 15 13:52:01.560: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc0040562c0, 0x70bd1d0, 0x19, 0xc003d422c8, 0x4, 0xc000109000)
... skipping 71 lines ...
Sep 15 13:56:38.207: INFO: PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 found and phase=Bound (4m36.617324637s)
Sep 15 13:56:43.241: INFO: PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 found and phase=Bound (4m41.651828159s)
Sep 15 13:56:48.270: INFO: PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 found and phase=Bound (4m46.680051194s)
Sep 15 13:56:53.299: INFO: PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 found and phase=Bound (4m51.709124423s)
Sep 15 13:56:58.327: INFO: PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 found and phase=Bound (4m56.737776378s)
STEP: Deleting sc
Sep 15 13:57:03.359: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 not deleted by dynamic provisioner: PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-abc94fc0-c13f-44e7-a8a2-e396bdc435d2 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, 0xc003d4acc0)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc002548820, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc001e32000, 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(0xc002548820, 0x4c, 0xc001f48c38, 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(0xc003cfbec0, 0x37, 0xc0020a7310, 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(0xc001f48dc0, 0x7904368, 0xc002505c90, 0x1, 0x0, 0x0, 0x0, 0xc002505c90)
	/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(0xc001f48dc0, 0x7904368, 0xc002505c90, 0x0, 0x0, 0x0, 0xc000108800)
	/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, 0xc002505c60, 0x6323060, 0xc002505c80, 0x0, 0x0, 0x0)
... skipping 140 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents","total":13,"completed":4,"skipped":327,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:57:04.330: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 51 lines ...
Sep 15 13:52:21.877: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-8223 PodName:pod-b9794e5b-b53b-442c-b688-6f9e9cf204d7 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:52:21.877: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:52:22.227: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-8223 PodName:pod-b9794e5b-b53b-442c-b688-6f9e9cf204d7 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:52:22.227: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:52:22.544: INFO: pod fsgroupchangepolicy-8223/pod-b9794e5b-b53b-442c-b688-6f9e9cf204d7 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 15 13:52 /mnt/volume1/subdir/file2, stderr: 
Sep 15 13:52:22.544: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 15 13:52 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 15 13:52:22.544: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc001c898c0, 0x70bd1d0, 0x19, 0xc0040c9f58, 0x4, 0xc00453a800)
... skipping 71 lines ...
Sep 15 13:56:59.237: INFO: PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b found and phase=Bound (4m36.662971905s)
Sep 15 13:57:04.266: INFO: PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b found and phase=Bound (4m41.692348575s)
Sep 15 13:57:09.298: INFO: PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b found and phase=Bound (4m46.723873888s)
Sep 15 13:57:14.326: INFO: PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b found and phase=Bound (4m51.752603017s)
Sep 15 13:57:19.356: INFO: PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b found and phase=Bound (4m56.782321702s)
STEP: Deleting sc
Sep 15 13:57:24.389: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b not deleted by dynamic provisioner: PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-3c7f1b69-129c-4370-9f6a-2abfe656477b 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, 0xc004694c40)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc000642dc0, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc000db0000, 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(0xc000642dc0, 0x4c, 0xc00284ec38, 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(0xc0021c2b40, 0x37, 0xc0045419d0, 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(0xc00284edc0, 0x7904368, 0xc003c55100, 0x1, 0x0, 0x0, 0x0, 0xc003c55100)
	/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(0xc00284edc0, 0x7904368, 0xc003c55100, 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, 0xc003c550e0, 0x6323060, 0xc003c550f0, 0x0, 0x0, 0x0)
... skipping 140 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with same fsgroup skips ownership changes to the volume contents","total":12,"completed":2,"skipped":879,"failed":1,"failures":["External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with same fsgroup skips ownership changes to the volume contents"]}

SSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:57:25.328: INFO: Driver "test.csi.azure.com" does not support block volume mode - skipping
... skipping 61 lines ...
Sep 15 13:53:22.953: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-1474 PodName:pod-7cee1ba3-ccc4-483d-a90f-dd86e8f070b2 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:53:22.953: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:53:23.375: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-1474 PodName:pod-7cee1ba3-ccc4-483d-a90f-dd86e8f070b2 ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:53:23.375: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:53:23.752: INFO: pod fsgroupchangepolicy-1474/pod-7cee1ba3-ccc4-483d-a90f-dd86e8f070b2 exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 15 13:53 /mnt/volume1/subdir/file2, stderr: 
Sep 15 13:53:23.752: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 15 13:53 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 15 13:53:23.752: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc002e16000, 0x70bd1d0, 0x19, 0xc0019444b8, 0x4, 0xc003c01000)
... skipping 71 lines ...
Sep 15 13:58:00.523: INFO: PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd found and phase=Bound (4m36.73689676s)
Sep 15 13:58:05.552: INFO: PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd found and phase=Bound (4m41.76549952s)
Sep 15 13:58:10.581: INFO: PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd found and phase=Bound (4m46.79510102s)
Sep 15 13:58:15.614: INFO: PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd found and phase=Bound (4m51.828080644s)
Sep 15 13:58:20.643: INFO: PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd found and phase=Bound (4m56.856611988s)
STEP: Deleting sc
Sep 15 13:58:25.675: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd not deleted by dynamic provisioner: PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-75931cf3-32fe-4d7c-adcd-ee32a57004dd 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, 0xc003fe2680)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc002590af0, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc002df7900, 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(0xc002590af0, 0x4c, 0xc002528c38, 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(0xc001c101c0, 0x37, 0xc003fab760, 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(0xc002528dc0, 0x7904368, 0xc002d938c0, 0x1, 0x0, 0x0, 0x0, 0xc002d938c0)
	/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(0xc002528dc0, 0x7904368, 0xc002d938c0, 0x0, 0x0, 0x0, 0xc0036bc000)
	/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, 0xc002d938a0, 0x6323060, 0xc002d938b0, 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 same fsgroup applied to the volume contents","total":21,"completed":3,"skipped":649,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[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 15 13:58:26.676: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 36 lines ...
Sep 15 13:58:26.856: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
Sep 15 13:58:26.886: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [test.csi.azure.com87xks] to have phase Bound
Sep 15 13:58:26.914: INFO: PersistentVolumeClaim test.csi.azure.com87xks found but phase is Pending instead of Bound.
Sep 15 13:58:28.943: INFO: PersistentVolumeClaim test.csi.azure.com87xks found and phase=Bound (2.056539706s)
STEP: Creating pod pod-subpath-test-dynamicpv-xwbp
STEP: Creating a pod to test subpath
Sep 15 13:58:29.031: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-xwbp" in namespace "provisioning-9677" to be "Succeeded or Failed"
Sep 15 13:58:29.059: INFO: Pod "pod-subpath-test-dynamicpv-xwbp": Phase="Pending", Reason="", readiness=false. Elapsed: 27.535656ms
Sep 15 13:58:31.087: INFO: Pod "pod-subpath-test-dynamicpv-xwbp": Phase="Pending", Reason="", readiness=false. Elapsed: 2.056040276s
Sep 15 13:58:33.117: INFO: Pod "pod-subpath-test-dynamicpv-xwbp": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.085764418s
STEP: Saw pod success
Sep 15 13:58:33.117: INFO: Pod "pod-subpath-test-dynamicpv-xwbp" satisfied condition "Succeeded or Failed"
Sep 15 13:58:33.145: INFO: Trying to get logs from node k8s-agentpool1-23004258-vmss000000 pod pod-subpath-test-dynamicpv-xwbp container test-container-subpath-dynamicpv-xwbp: <nil>
STEP: delete the pod
Sep 15 13:58:33.210: INFO: Waiting for pod pod-subpath-test-dynamicpv-xwbp to disappear
Sep 15 13:58:33.239: INFO: Pod pod-subpath-test-dynamicpv-xwbp no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-xwbp
Sep 15 13:58:33.239: INFO: Deleting pod "pod-subpath-test-dynamicpv-xwbp" in namespace "provisioning-9677"
... 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":21,"completed":4,"skipped":707,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
External Storage [Driver: test.csi.azure.com] [Testpattern: Generic Ephemeral-volume (default fs) (late-binding)] ephemeral 
  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
... skipping 36 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":21,"completed":5,"skipped":847,"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"]}

SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
------------------------------
[BeforeEach] [Testpattern: Pre-provisioned PV (block volmode)] volumes
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
Sep 15 13:59:19.989: INFO: Driver "test.csi.azure.com" does not support volume type "PreprovisionedPV" - skipping
... skipping 61 lines ...
Sep 15 13:56:41.092: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-1953 PodName:pod-75ed2c5f-64af-40e4-918a-6fe16ffb3d9e ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:56:41.092: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:56:41.426: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-1953 PodName:pod-75ed2c5f-64af-40e4-918a-6fe16ffb3d9e ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:56:41.426: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:56:41.823: INFO: pod fsgroupchangepolicy-1953/pod-75ed2c5f-64af-40e4-918a-6fe16ffb3d9e exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 15 13:56 /mnt/volume1/subdir/file2, stderr: 
Sep 15 13:56:41.824: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 15 13:56 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 15 13:56:41.824: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc002eefce0, 0x70bd1d0, 0x19, 0xc003a04168, 0x4, 0xc002df8c00)
... skipping 71 lines ...
Sep 15 14:01:18.523: INFO: PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da found and phase=Bound (4m36.669469687s)
Sep 15 14:01:23.554: INFO: PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da found and phase=Bound (4m41.700416438s)
Sep 15 14:01:28.583: INFO: PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da found and phase=Bound (4m46.729369497s)
Sep 15 14:01:33.614: INFO: PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da found and phase=Bound (4m51.760191307s)
Sep 15 14:01:38.645: INFO: PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da found and phase=Bound (4m56.791321836s)
STEP: Deleting sc
Sep 15 14:01:43.678: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da not deleted by dynamic provisioner: PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-e0cbea9e-4b96-4b86-89e6-174da0e610da 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, 0xc00320ec00)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc002b17e00, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc001325400, 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(0xc002b17e00, 0x4c, 0xc00152cc38, 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(0xc003bd1280, 0x37, 0xc002c1eea0, 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(0xc00152cdc0, 0x7904368, 0xc004c37ff0, 0x1, 0x0, 0x0, 0x0, 0xc004c37ff0)
	/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(0xc00152cdc0, 0x7904368, 0xc004c37ff0, 0x0, 0x0, 0x0, 0xc000093400)
	/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, 0xc004c37fd0, 0x6323060, 0xc004c37fe0, 0x0, 0x0, 0x0)
... skipping 136 lines ...
        <string>: root
    to equal
        <string>: 1000

    /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728
------------------------------
{"msg":"FAILED External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents","total":14,"completed":1,"skipped":845,"failed":2,"failures":["External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents","External Storage [Driver: test.csi.azure.com] [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy (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"]}

SSSSSSS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeLimits
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeLimits
... skipping 112 lines ...
Sep 15 13:57:10.023: INFO: ExecWithOptions {Command:[/bin/sh -c touch /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-9338 PodName:pod-c268da71-01fa-4a53-9480-247e95cfda2d ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:57:10.023: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:57:10.366: INFO: ExecWithOptions {Command:[/bin/sh -c ls -l /mnt/volume1/subdir/file2] Namespace:fsgroupchangepolicy-9338 PodName:pod-c268da71-01fa-4a53-9480-247e95cfda2d ContainerName:write-pod Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Sep 15 13:57:10.366: INFO: >>> kubeConfig: /root/tmp2328744745/kubeconfig/kubeconfig.eastus.json
Sep 15 13:57:10.745: INFO: pod fsgroupchangepolicy-9338/pod-c268da71-01fa-4a53-9480-247e95cfda2d exec for cmd ls -l /mnt/volume1/subdir/file2, stdout: -rw-r--r--    1 root     root             0 Sep 15 13:57 /mnt/volume1/subdir/file2, stderr: 
Sep 15 13:57:10.745: INFO: stdout split: [-rw-r--r-- 1 root root 0 Sep 15 13:57 /mnt/volume1/subdir/file2], expected gid: 1000
Sep 15 13:57:10.745: FAIL: Expected
    <string>: root
to equal
    <string>: 1000

Full Stack Trace
k8s.io/kubernetes/test/e2e/storage/utils.VerifyFilePathGidInPod(0xc0040562c0, 0x70bd1d0, 0x19, 0xc0042d8a68, 0x4, 0xc00389b000)
... skipping 71 lines ...
Sep 15 14:01:47.404: INFO: PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 found and phase=Bound (4m36.628703308s)
Sep 15 14:01:52.440: INFO: PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 found and phase=Bound (4m41.663859413s)
Sep 15 14:01:57.475: INFO: PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 found and phase=Bound (4m46.699069121s)
Sep 15 14:02:02.505: INFO: PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 found and phase=Bound (4m51.729224926s)
Sep 15 14:02:07.536: INFO: PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 found and phase=Bound (4m56.760776088s)
STEP: Deleting sc
Sep 15 14:02:12.566: FAIL: while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        [
            {
                msg: "persistent Volume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 not deleted by dynamic provisioner: PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 still exists within 5m0s",
                err: {
                    s: "PersistentVolume pvc-ad9314f5-5758-4e77-a64b-c89439772a33 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, 0xc004254680)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail.func1(0xc004060550, 0x4c, 0x895c71a, 0x6c, 0x2d8, 0xc001e32000, 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(0xc004060550, 0x4c, 0xc001f48c38, 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(0xc002c705c0, 0x37, 0xc002b62190, 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(0xc001f48dc0, 0x7904368, 0xc0043d4de0, 0x1, 0x0, 0x0, 0x0, 0xc0043d4de0)
	/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(0xc001f48dc0, 0x7904368, 0xc0043d4de0, 0x0, 0x0, 0x0, 0xc000108800)
	/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, 0xc0043d4dc0, 0x6323060, 0xc0043d4dd0, 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 (Always)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents","total":13,"completed":4,"skipped":564,"failed":2,"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","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"]}

SSSSSSSSSSSS
------------------------------
[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 15 14:02:13.473: INFO: Driver test.csi.azure.com doesn't support ntfs -- skipping
... skipping 99 lines ...
Sep 15 14:02:13.870: 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] (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

[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, 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, new pod fsgroup applied to volume contents 
/workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/utils.go:728

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

Ginkgo ran 1 suite in 12m33.267758002s
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:
I0915 13:49:38.309559       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 gc/go1.17.1 (amd64-linux) e2e-test
I0915 13:49:38.310501       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0915 13:49:38.334063       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
I0915 13:49:38.334081       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0915 13:49:38.334087       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0915 13:49:38.334114       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0915 13:49:38.334680       1 azure_auth.go:234] Using AzurePublicCloud environment
I0915 13:49:38.334710       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0915 13:49:38.334731       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 624 lines ...
Go Version: go1.17.1
Platform: linux/amd64

Streaming logs below:
I0915 13:49:39.044855       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 gc/go1.17.1 (amd64-linux) e2e-test
I0915 13:49:39.045766       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0915 13:49:39.071125       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
I0915 13:49:39.071144       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0915 13:49:39.071150       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0915 13:49:39.071177       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0915 13:49:39.071660       1 azure_auth.go:234] Using AzurePublicCloud environment
I0915 13:49:39.071684       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0915 13:49:39.071705       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 117 lines ...
Go Version: go1.17.1
Platform: linux/amd64

Streaming logs below:
I0915 13:49:34.021756       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 gc/go1.17.1 (amd64-linux) e2e-test
I0915 13:49:34.022634       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0915 13:49:34.040873       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
I0915 13:49:34.040891       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0915 13:49:34.040898       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0915 13:49:34.040916       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0915 13:49:34.041428       1 azure_auth.go:234] Using AzurePublicCloud environment
I0915 13:49:34.041459       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0915 13:49:34.041485       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 582 lines ...
Go Version: go1.17.1
Platform: linux/amd64

Streaming logs below:
I0915 13:49:26.553916       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 gc/go1.17.1 (amd64-linux) e2e-test
I0915 13:49:26.554772       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0915 13:49:26.576199       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
I0915 13:49:26.576219       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0915 13:49:26.576224       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0915 13:49:26.576249       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0915 13:49:26.576878       1 azure_auth.go:234] Using AzurePublicCloud environment
I0915 13:49:26.576980       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0915 13:49:26.577008       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:
I0915 13:49:32.649949       1 azurefile.go:233] driver userAgent: test.csi.azure.com/e2e-75e48458c73f549a3aa0cdc1d7ad3e9a9e52f2d5 gc/go1.17.1 (amd64-linux) e2e-test
I0915 13:49:32.651292       1 azure.go:70] reading cloud config from secret kube-system/azure-cloud-provider
W0915 13:49:32.674666       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
I0915 13:49:32.674688       1 azure.go:82] could not read cloud config from secret kube-system/azure-cloud-provider
I0915 13:49:32.674694       1 azure.go:92] use default AZURE_CREDENTIAL_FILE env var: /etc/kubernetes/azure.json
I0915 13:49:32.674717       1 azure.go:100] read cloud config from file: /etc/kubernetes/azure.json successfully
I0915 13:49:32.675230       1 azure_auth.go:234] Using AzurePublicCloud environment
I0915 13:49:32.675261       1 azure_auth.go:119] azure: using client_id+client_secret to retrieve access token
I0915 13:49:32.675284       1 azure.go:685] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
... skipping 828 lines ...
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 7.61909248e+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/15 14:03:05 process.go:155: Step 'make e2e-test' finished in 23m6.162147805s
2021/09/15 14:03:05 aksengine_helpers.go:425: downloading /root/tmp2328744745/log-dump.sh from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh
2021/09/15 14:03:05 util.go:68: curl https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump.sh
2021/09/15 14:03:05 process.go:153: Running: chmod +x /root/tmp2328744745/log-dump.sh
2021/09/15 14:03:05 process.go:155: Step 'chmod +x /root/tmp2328744745/log-dump.sh' finished in 1.080428ms
2021/09/15 14:03:05 aksengine_helpers.go:425: downloading /root/tmp2328744745/log-dump-daemonset.yaml from https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/master/hack/log-dump/log-dump-daemonset.yaml
... skipping 52 lines ...
ssh key file /root/.ssh/id_rsa does not exist. Exiting.
2021/09/15 14:03:30 process.go:155: Step 'bash -c /root/tmp2328744745/win-ci-logs-collector.sh kubetest-hjrzbnvl.eastus.cloudapp.azure.com /root/tmp2328744745 /root/.ssh/id_rsa' finished in 2.961745ms
2021/09/15 14:03:30 aksengine.go:1141: Deleting resource group: kubetest-hjrzbnvl.
2021/09/15 14:11:34 process.go:96: Saved XML output to /logs/artifacts/junit_runner.xml.
2021/09/15 14:11:34 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"
2021/09/15 14:11:34 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 267.264539ms
2021/09/15 14:11:34 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
50cec626d8bd
... skipping 4 lines ...