This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 1 failed / 65 succeeded
Started2022-09-24 11:07
Elapsed29m10s
Revisionmaster

Test Failures


EBS CSI Migration Suite [ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] should access to two volumes with different volume mode and retain data across pod recreation on the same node 6m7s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=EBS\sCSI\sMigration\sSuite\s\[ebs\-csi\-migration\]\sEBS\sCSI\sMigration\s\[Driver\:\saws\]\s\[Testpattern\:\sDynamic\sPV\s\(ext4\)\]\smultiVolume\s\[Slow\]\sshould\saccess\sto\stwo\svolumes\swith\sdifferent\svolume\smode\sand\sretain\sdata\sacross\spod\srecreation\son\sthe\ssame\snode$'
/home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:206
while cleanup resource
Unexpected error:
    <errors.aggregate | len:1, cap:1>: [
        <errors.aggregate | len:1, cap:1>[
            <*fmt.wrapError | 0xc000b76400>{
                msg: "persistent Volume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 not deleted by dynamic provisioner: PersistentVolume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 still exists within 5m0s",
                err: <*errors.errorString | 0xc0010ae550>{
                    s: "PersistentVolume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 still exists within 5m0s",
                },
            },
        ],
    ]
    persistent Volume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 not deleted by dynamic provisioner: PersistentVolume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 still exists within 5m0s
occurred
/home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:126
				
				Click to see stdout/stderrfrom junit_02.xml

Filter through log files | View test history on testgrid


Show 65 Passed Tests

Show 473 Skipped Tests

Error lines from build-log.txt

... skipping 182 lines ...
|.o o oo S ...+++ |
|o o .o   .oo+o=oo|
|   .+    + oo+.o+|
|   o..    o o  oB|
|   ..      E. .==|
+----[SHA256]-----+
Error: cluster not found "test-cluster-18977.k8s.local"
###
## Creating cluster test-cluster-18977.k8s.local with /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.yaml (dry run)
#
I0924 11:09:30.002288    5792 create_cluster.go:843] Using SSH public key: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/id_rsa.pub
I0924 11:09:30.754347    5792 new_cluster.go:248] Inferred "aws" cloud provider from zone "us-west-2a"
I0924 11:09:30.754688    5792 new_cluster.go:1102]  Cloud Provider ID = aws
... skipping 76 lines ...
## Validating cluster test-cluster-18977.k8s.local
#
Using cluster from kubectl context: test-cluster-18977.k8s.local

Validating cluster test-cluster-18977.k8s.local

W0924 11:10:44.077931    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:10:54.125999    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:04.173951    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:14.221205    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:24.315572    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:34.348958    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:45.540172    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:12:08.325116    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:12:30.011240    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:12:51.692225    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:13:13.463850    5935 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-18977-k8-pfm957-2112822492.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
nodes-us-west-2c	Node	c5.large	1	1	us-west-2c
... skipping 6 lines ...
KIND	NAME						MESSAGE
Machine	i-092f97c29f01b8a1b				machine "i-092f97c29f01b8a1b" has not yet joined cluster
Machine	i-0efded25a41d8b33d				machine "i-0efded25a41d8b33d" has not yet joined cluster
Machine	i-0f966478d3398b066				machine "i-0f966478d3398b066" has not yet joined cluster
Node	ip-172-20-40-128.us-west-2.compute.internal	node "ip-172-20-40-128.us-west-2.compute.internal" of role "master" is not ready

Validation Failed
W0924 11:13:29.775264    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 7 lines ...
KIND	NAME						MESSAGE
Machine	i-092f97c29f01b8a1b				machine "i-092f97c29f01b8a1b" has not yet joined cluster
Machine	i-0efded25a41d8b33d				machine "i-0efded25a41d8b33d" has not yet joined cluster
Machine	i-0f966478d3398b066				machine "i-0f966478d3398b066" has not yet joined cluster
Node	ip-172-20-40-128.us-west-2.compute.internal	node "ip-172-20-40-128.us-west-2.compute.internal" of role "master" is not ready

Validation Failed
W0924 11:13:42.052035    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 11 lines ...
Node	ip-172-20-40-128.us-west-2.compute.internal	node "ip-172-20-40-128.us-west-2.compute.internal" of role "master" is not ready
Pod	kube-system/coredns-6d467c5d59-jdn8n		system-cluster-critical pod "coredns-6d467c5d59-jdn8n" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-55jm5	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-55jm5" is pending
Pod	kube-system/dns-controller-7c956b559c-ql7m9	system-cluster-critical pod "dns-controller-7c956b559c-ql7m9" is pending
Pod	kube-system/kops-controller-jqvs6		system-cluster-critical pod "kops-controller-jqvs6" is pending

Validation Failed
W0924 11:13:54.407369    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 11 lines ...
Node	ip-172-20-40-128.us-west-2.compute.internal	master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-apiserver pod
Node	ip-172-20-40-128.us-west-2.compute.internal	master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-controller-manager pod
Pod	kube-system/coredns-6d467c5d59-jdn8n		system-cluster-critical pod "coredns-6d467c5d59-jdn8n" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-55jm5	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-55jm5" is pending
Pod	kube-system/kops-controller-jqvs6		system-cluster-critical pod "kops-controller-jqvs6" is pending

Validation Failed
W0924 11:14:06.591048    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 10 lines ...
Machine	i-0f966478d3398b066				machine "i-0f966478d3398b066" has not yet joined cluster
Node	ip-172-20-40-128.us-west-2.compute.internal	master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-apiserver pod
Node	ip-172-20-40-128.us-west-2.compute.internal	master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-controller-manager pod
Pod	kube-system/coredns-6d467c5d59-jdn8n		system-cluster-critical pod "coredns-6d467c5d59-jdn8n" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-55jm5	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-55jm5" is pending

Validation Failed
W0924 11:14:18.719536    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 10 lines ...
Machine	i-0f966478d3398b066				machine "i-0f966478d3398b066" has not yet joined cluster
Node	ip-172-20-40-128.us-west-2.compute.internal	master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-apiserver pod
Node	ip-172-20-40-128.us-west-2.compute.internal	master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-controller-manager pod
Pod	kube-system/coredns-6d467c5d59-jdn8n		system-cluster-critical pod "coredns-6d467c5d59-jdn8n" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-55jm5	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-55jm5" is pending

Validation Failed
W0924 11:14:30.842568    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 12 lines ...
Node	ip-172-20-40-128.us-west-2.compute.internal					master "ip-172-20-40-128.us-west-2.compute.internal" is missing kube-controller-manager pod
Pod	kube-system/coredns-6d467c5d59-jdn8n						system-cluster-critical pod "coredns-6d467c5d59-jdn8n" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-55jm5					system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-55jm5" is pending
Pod	kube-system/kube-apiserver-ip-172-20-40-128.us-west-2.compute.internal		system-cluster-critical pod "kube-apiserver-ip-172-20-40-128.us-west-2.compute.internal" is pending
Pod	kube-system/kube-controller-manager-ip-172-20-40-128.us-west-2.compute.internal	system-cluster-critical pod "kube-controller-manager-ip-172-20-40-128.us-west-2.compute.internal" is pending

Validation Failed
W0924 11:14:42.917285    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 11 lines ...
Node	ip-172-20-110-116.us-west-2.compute.internal	node "ip-172-20-110-116.us-west-2.compute.internal" of role "node" is not ready
Node	ip-172-20-49-28.us-west-2.compute.internal	node "ip-172-20-49-28.us-west-2.compute.internal" of role "node" is not ready
Node	ip-172-20-69-106.us-west-2.compute.internal	node "ip-172-20-69-106.us-west-2.compute.internal" of role "node" is not ready
Pod	kube-system/coredns-6d467c5d59-jdn8n		system-cluster-critical pod "coredns-6d467c5d59-jdn8n" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-55jm5	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-55jm5" is pending

Validation Failed
W0924 11:14:55.138836    5935 validate_cluster.go:232] (will retry): cluster not yet healthy
INSTANCE GROUPS
NAME			ROLE	MACHINETYPE	MIN	MAX	SUBNETS
master-us-west-2a	Master	t3.medium	1	1	us-west-2a
nodes-us-west-2a	Node	c5.large	1	1	us-west-2a
nodes-us-west-2b	Node	c5.large	1	1	us-west-2b
... skipping 177 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Inline-volume (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath file is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:256

      Driver supports dynamic provisioning, skipping InlineVolume pattern

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/base.go:244
------------------------------
... skipping 17 lines ...
Sep 24 11:17:03.022: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
STEP: creating a test aws volume
Sep 24 11:17:03.558: INFO: Successfully created a new PD: "aws://us-west-2a/vol-054dae92aece896e6".
Sep 24 11:17:03.558: INFO: Creating resource for inline volume
STEP: Creating pod exec-volume-test-inlinevolume-qgf7
STEP: Creating a pod to test exec-volume-test
Sep 24 11:17:03.626: INFO: Waiting up to 5m0s for pod "exec-volume-test-inlinevolume-qgf7" in namespace "volume-4709" to be "Succeeded or Failed"
Sep 24 11:17:03.690: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Pending", Reason="", readiness=false. Elapsed: 64.477143ms
Sep 24 11:17:05.761: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.134687047s
Sep 24 11:17:07.831: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205576966s
Sep 24 11:17:09.896: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Pending", Reason="", readiness=false. Elapsed: 6.270492449s
Sep 24 11:17:11.961: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Pending", Reason="", readiness=false. Elapsed: 8.335235657s
Sep 24 11:17:14.026: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Pending", Reason="", readiness=false. Elapsed: 10.399726172s
Sep 24 11:17:16.092: INFO: Pod "exec-volume-test-inlinevolume-qgf7": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.465813033s
STEP: Saw pod success
Sep 24 11:17:16.092: INFO: Pod "exec-volume-test-inlinevolume-qgf7" satisfied condition "Succeeded or Failed"
Sep 24 11:17:16.155: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod exec-volume-test-inlinevolume-qgf7 container exec-container-inlinevolume-qgf7: <nil>
STEP: delete the pod
Sep 24 11:17:16.306: INFO: Waiting for pod exec-volume-test-inlinevolume-qgf7 to disappear
Sep 24 11:17:16.370: INFO: Pod exec-volume-test-inlinevolume-qgf7 no longer exists
STEP: Deleting pod exec-volume-test-inlinevolume-qgf7
Sep 24 11:17:16.370: INFO: Deleting pod "exec-volume-test-inlinevolume-qgf7" in namespace "volume-4709"
Sep 24 11:17:16.569: INFO: Couldn't delete PD "aws://us-west-2a/vol-054dae92aece896e6", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-054dae92aece896e6 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 9b813ec6-5cdf-4d83-a594-cbde100fb7fd
Sep 24 11:17:21.949: INFO: Couldn't delete PD "aws://us-west-2a/vol-054dae92aece896e6", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-054dae92aece896e6 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 5ae97f56-a8a0-4fef-8f38-a25c1d41cd29
Sep 24 11:17:27.326: INFO: Couldn't delete PD "aws://us-west-2a/vol-054dae92aece896e6", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-054dae92aece896e6 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 65979f18-8aec-41a1-9ced-2a0b2ee5fbc3
Sep 24 11:17:32.723: INFO: Successfully deleted PD "aws://us-west-2a/vol-054dae92aece896e6".
[AfterEach] [Testpattern: Inline-volume (ext4)] volumes
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:186
Sep 24 11:17:32.723: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "volume-4709" for this suite.
... skipping 7 lines ...
    [Testpattern: Inline-volume (ext4)] volumes
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should allow exec of files on the volume
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumes.go:196
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if subpath directory is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:240

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:17:02.473: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename provisioning
Sep 24 11:17:02.929: INFO: No PodSecurityPolicies found; assuming PodSecurityPolicy is disabled.
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail if subpath directory is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:240
Sep 24 11:17:03.063: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:17:03.063: INFO: Creating resource for dynamic PV
Sep 24 11:17:03.063: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-2876vmpnj
STEP: creating a claim
Sep 24 11:17:03.131: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-mww7
STEP: Checking for subpath error in container status
Sep 24 11:17:31.483: INFO: Deleting pod "pod-subpath-test-dynamicpv-mww7" in namespace "provisioning-2876"
Sep 24 11:17:31.553: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-mww7" to be fully deleted
STEP: Deleting pod
Sep 24 11:17:37.689: INFO: Deleting pod "pod-subpath-test-dynamicpv-mww7" in namespace "provisioning-2876"
STEP: Deleting pvc
Sep 24 11:17:37.901: INFO: Deleting PersistentVolumeClaim "awscqbk4"
... skipping 13 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath directory is outside the volume [Slow][LinuxOnly]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:240
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] 
  should concurrently access the single read-only volume from pods on the same node
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:432

... skipping 289 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:278

      Distro debian doesn't support ntfs -- skipping

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 90 lines ...
Sep 24 11:18:29.514: INFO: Pod aws-client still exists
Sep 24 11:18:31.515: INFO: Waiting for pod aws-client to disappear
Sep 24 11:18:31.583: INFO: Pod aws-client still exists
Sep 24 11:18:33.515: INFO: Waiting for pod aws-client to disappear
Sep 24 11:18:33.585: INFO: Pod aws-client no longer exists
STEP: cleaning the environment after aws
Sep 24 11:18:33.721: INFO: Couldn't delete PD "aws://us-west-2a/vol-0fccd84921e2dae76", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0fccd84921e2dae76 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 0b1492cd-dd99-4015-8fcf-4149b17c83e4
Sep 24 11:18:39.110: INFO: Couldn't delete PD "aws://us-west-2a/vol-0fccd84921e2dae76", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0fccd84921e2dae76 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 5e9a724e-978d-428d-b66d-d19a86005673
Sep 24 11:18:44.494: INFO: Couldn't delete PD "aws://us-west-2a/vol-0fccd84921e2dae76", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0fccd84921e2dae76 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: a608588e-2864-41d5-b455-188f68d83dd9
Sep 24 11:18:49.905: INFO: Successfully deleted PD "aws://us-west-2a/vol-0fccd84921e2dae76".
[AfterEach] [Testpattern: Inline-volume (default fs)] volumes
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:186
Sep 24 11:18:49.905: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "volume-8979" for this suite.
... skipping 474 lines ...
Sep 24 11:18:50.413: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-3712xpgkc
STEP: creating a claim
Sep 24 11:18:50.482: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-k26n
STEP: Creating a pod to test subpath
Sep 24 11:18:50.688: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-k26n" in namespace "provisioning-3712" to be "Succeeded or Failed"
Sep 24 11:18:50.755: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 67.12713ms
Sep 24 11:18:52.824: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 2.136190186s
Sep 24 11:18:54.895: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207047513s
Sep 24 11:18:56.963: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 6.275365387s
Sep 24 11:18:59.032: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 8.343707155s
Sep 24 11:19:01.101: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 10.4131872s
Sep 24 11:19:03.171: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 12.482531103s
Sep 24 11:19:05.254: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Pending", Reason="", readiness=false. Elapsed: 14.56609273s
Sep 24 11:19:07.322: INFO: Pod "pod-subpath-test-dynamicpv-k26n": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.634391857s
STEP: Saw pod success
Sep 24 11:19:07.322: INFO: Pod "pod-subpath-test-dynamicpv-k26n" satisfied condition "Succeeded or Failed"
Sep 24 11:19:07.390: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-k26n container test-container-volume-dynamicpv-k26n: <nil>
STEP: delete the pod
Sep 24 11:19:07.552: INFO: Waiting for pod pod-subpath-test-dynamicpv-k26n to disappear
Sep 24 11:19:07.618: INFO: Pod pod-subpath-test-dynamicpv-k26n no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-k26n
Sep 24 11:19:07.618: INFO: Deleting pod "pod-subpath-test-dynamicpv-k26n" in namespace "provisioning-3712"
... skipping 162 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath file is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:256

      Distro debian doesn't support ntfs -- skipping

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 245 lines ...

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/base.go:244
------------------------------
S
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (block volmode)] volumeMode 
  should fail to use a volume in a pod with mismatched mode [Slow]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumemode.go:297

[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:19:23.964: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename volumemode
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail to use a volume in a pod with mismatched mode [Slow]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumemode.go:297
Sep 24 11:19:24.303: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:19:24.303: INFO: Creating resource for dynamic PV
Sep 24 11:19:24.303: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass volumemode-881847vgn
STEP: creating a claim
STEP: Creating pod
STEP: Waiting for the pod to fail
Sep 24 11:19:30.779: INFO: Deleting pod "pod-1fd0bd5f-08c6-477a-9792-67c714bb5fea" in namespace "volumemode-8818"
Sep 24 11:19:30.848: INFO: Wait up to 5m0s for pod "pod-1fd0bd5f-08c6-477a-9792-67c714bb5fea" to be fully deleted
STEP: Deleting pvc
Sep 24 11:19:39.116: INFO: Deleting PersistentVolumeClaim "awskzlz8"
Sep 24 11:19:39.193: INFO: Waiting up to 5m0s for PersistentVolume pvc-14d1bd06-5388-4be2-89ac-95ef27158691 to get deleted
Sep 24 11:19:39.259: INFO: PersistentVolume pvc-14d1bd06-5388-4be2-89ac-95ef27158691 found and phase=Released (66.61544ms)
... skipping 9 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (block volmode)] volumeMode
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail to use a volume in a pod with mismatched mode [Slow]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumemode.go:297
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (block volmode)] volumes 
  should store data
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumes.go:159

... skipping 127 lines ...
Sep 24 11:19:55.174: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-7724wbdfm
STEP: creating a claim
Sep 24 11:19:55.239: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-gxk9
STEP: Creating a pod to test subpath
Sep 24 11:19:55.437: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-gxk9" in namespace "provisioning-7724" to be "Succeeded or Failed"
Sep 24 11:19:55.500: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Pending", Reason="", readiness=false. Elapsed: 63.55904ms
Sep 24 11:19:57.565: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.128387122s
Sep 24 11:19:59.630: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.193425555s
Sep 24 11:20:01.699: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.262266442s
Sep 24 11:20:03.764: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.327058303s
Sep 24 11:20:05.829: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Pending", Reason="", readiness=false. Elapsed: 10.39221361s
Sep 24 11:20:07.894: INFO: Pod "pod-subpath-test-dynamicpv-gxk9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.457157358s
STEP: Saw pod success
Sep 24 11:20:07.894: INFO: Pod "pod-subpath-test-dynamicpv-gxk9" satisfied condition "Succeeded or Failed"
Sep 24 11:20:07.961: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-gxk9 container test-container-volume-dynamicpv-gxk9: <nil>
STEP: delete the pod
Sep 24 11:20:08.101: INFO: Waiting for pod pod-subpath-test-dynamicpv-gxk9 to disappear
Sep 24 11:20:08.167: INFO: Pod pod-subpath-test-dynamicpv-gxk9 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-gxk9
Sep 24 11:20:08.167: INFO: Deleting pod "pod-subpath-test-dynamicpv-gxk9" in namespace "provisioning-7724"
... skipping 175 lines ...

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:121
------------------------------
SSSSSSSS
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if subpath file is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:256

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:20:24.413: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename provisioning
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail if subpath file is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:256
Sep 24 11:20:24.737: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:20:24.737: INFO: Creating resource for dynamic PV
Sep 24 11:20:24.737: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-9251z4n2p
STEP: creating a claim
Sep 24 11:20:24.801: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-m4qf
STEP: Checking for subpath error in container status
Sep 24 11:20:35.129: INFO: Deleting pod "pod-subpath-test-dynamicpv-m4qf" in namespace "provisioning-9251"
Sep 24 11:20:35.195: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-m4qf" to be fully deleted
STEP: Deleting pod
Sep 24 11:20:47.324: INFO: Deleting pod "pod-subpath-test-dynamicpv-m4qf" in namespace "provisioning-9251"
STEP: Deleting pvc
Sep 24 11:20:47.518: INFO: Deleting PersistentVolumeClaim "awst89k9"
... skipping 11 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath file is outside the volume [Slow][LinuxOnly]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:256
------------------------------
SS
------------------------------
[BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
... skipping 137 lines ...
Sep 24 11:20:53.233: INFO: Using claimSize:1Gi, test suite supported size:{ 1Gi}, driver(aws) supported size:{ 1Gi} 
STEP: creating a StorageClass volume-expand-5258p4kwb
STEP: creating a claim
Sep 24 11:20:53.297: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Expanding non-expandable pvc
Sep 24 11:20:53.428: INFO: currentPvcSize {{1073741824 0} {<nil>} 1Gi BinarySI}, newSize {{2147483648 0} {<nil>}  BinarySI}
Sep 24 11:20:53.557: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:20:55.690: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:20:57.690: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:20:59.686: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:01.687: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:03.687: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:05.705: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:07.690: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:09.687: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:11.694: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:13.690: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:15.687: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:17.687: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:19.688: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:21.689: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:23.688: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-5258p4kwb",
  	... // 2 identical fields
  }

Sep 24 11:21:23.817: INFO: Error updating pvc awsfs2k7: PersistentVolumeClaim "awsfs2k7" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 180 lines ...
Sep 24 11:21:22.381: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-6926vrsgd
STEP: creating a claim
Sep 24 11:21:22.446: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-9c99
STEP: Creating a pod to test subpath
Sep 24 11:21:22.647: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-9c99" in namespace "provisioning-6926" to be "Succeeded or Failed"
Sep 24 11:21:22.712: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 65.52149ms
Sep 24 11:21:24.780: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 2.133104781s
Sep 24 11:21:26.846: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 4.199411407s
Sep 24 11:21:28.911: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 6.264553202s
Sep 24 11:21:30.979: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 8.332554251s
Sep 24 11:21:33.045: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 10.398084394s
Sep 24 11:21:35.124: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 12.477027457s
Sep 24 11:21:37.191: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Pending", Reason="", readiness=false. Elapsed: 14.544060488s
Sep 24 11:21:39.256: INFO: Pod "pod-subpath-test-dynamicpv-9c99": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.609249378s
STEP: Saw pod success
Sep 24 11:21:39.256: INFO: Pod "pod-subpath-test-dynamicpv-9c99" satisfied condition "Succeeded or Failed"
Sep 24 11:21:39.321: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-9c99 container test-container-subpath-dynamicpv-9c99: <nil>
STEP: delete the pod
Sep 24 11:21:39.471: INFO: Waiting for pod pod-subpath-test-dynamicpv-9c99 to disappear
Sep 24 11:21:39.536: INFO: Pod pod-subpath-test-dynamicpv-9c99 no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-9c99
Sep 24 11:21:39.536: INFO: Deleting pod "pod-subpath-test-dynamicpv-9c99" in namespace "provisioning-6926"
... skipping 44 lines ...
Sep 24 11:21:24.475: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-1189t7c5h
STEP: creating a claim
Sep 24 11:21:24.539: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-dr8m
STEP: Creating a pod to test subpath
Sep 24 11:21:24.734: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-dr8m" in namespace "provisioning-1189" to be "Succeeded or Failed"
Sep 24 11:21:24.798: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Pending", Reason="", readiness=false. Elapsed: 63.721457ms
Sep 24 11:21:26.862: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.128079144s
Sep 24 11:21:28.928: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.193288085s
Sep 24 11:21:30.992: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.257572039s
Sep 24 11:21:33.056: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.32179399s
Sep 24 11:21:35.131: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Pending", Reason="", readiness=false. Elapsed: 10.39681378s
Sep 24 11:21:37.196: INFO: Pod "pod-subpath-test-dynamicpv-dr8m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.461329329s
STEP: Saw pod success
Sep 24 11:21:37.196: INFO: Pod "pod-subpath-test-dynamicpv-dr8m" satisfied condition "Succeeded or Failed"
Sep 24 11:21:37.259: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-dr8m container test-container-subpath-dynamicpv-dr8m: <nil>
STEP: delete the pod
Sep 24 11:21:37.396: INFO: Waiting for pod pod-subpath-test-dynamicpv-dr8m to disappear
Sep 24 11:21:37.460: INFO: Pod pod-subpath-test-dynamicpv-dr8m no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-dr8m
Sep 24 11:21:37.460: INFO: Deleting pod "pod-subpath-test-dynamicpv-dr8m" in namespace "provisioning-1189"
... skipping 201 lines ...
    [Testpattern: Inline-volume (xfs)][Slow] volumes
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should store data
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumes.go:159
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (immediate binding)] topology 
  should fail to schedule a pod which has topologies that conflict with AllowedTopologies
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/topology.go:192

[BeforeEach] [Testpattern: Dynamic PV (immediate binding)] topology
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (immediate binding)] topology
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:22:39.347: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename topology
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail to schedule a pod which has topologies that conflict with AllowedTopologies
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/topology.go:192
Sep 24 11:22:39.738: INFO: found topology map[topology.kubernetes.io/zone:us-west-2c]
Sep 24 11:22:39.738: INFO: found topology map[topology.kubernetes.io/zone:us-west-2a]
Sep 24 11:22:39.738: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:22:39.738: INFO: Creating storage class object and pvc object for driver - sc: &StorageClass{ObjectMeta:{topology-9085xdsxg      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Provisioner:kubernetes.io/aws-ebs,Parameters:map[string]string{},ReclaimPolicy:nil,MountOptions:[],AllowVolumeExpansion:nil,VolumeBindingMode:*Immediate,AllowedTopologies:[]TopologySelectorTerm{{[{topology.kubernetes.io/zone [us-west-2a]}]},},}, pvc: &PersistentVolumeClaim{ObjectMeta:{ pvc- topology-9085    0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Spec:PersistentVolumeClaimSpec{AccessModes:[ReadWriteOnce],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},},VolumeName:,Selector:nil,StorageClassName:*topology-9085xdsxg,VolumeMode:nil,DataSource:nil,DataSourceRef:nil,},Status:PersistentVolumeClaimStatus{Phase:,AccessModes:[],Capacity:ResourceList{},Conditions:[]PersistentVolumeClaimCondition{},},}
STEP: Creating sc
... skipping 197 lines ...
Sep 24 11:22:44.701: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
STEP: creating a test aws volume
Sep 24 11:22:45.214: INFO: Successfully created a new PD: "aws://us-west-2a/vol-0652ebd634f63482e".
Sep 24 11:22:45.214: INFO: Creating resource for inline volume
STEP: Creating pod exec-volume-test-inlinevolume-hvr8
STEP: Creating a pod to test exec-volume-test
Sep 24 11:22:45.283: INFO: Waiting up to 5m0s for pod "exec-volume-test-inlinevolume-hvr8" in namespace "volume-387" to be "Succeeded or Failed"
Sep 24 11:22:45.350: INFO: Pod "exec-volume-test-inlinevolume-hvr8": Phase="Pending", Reason="", readiness=false. Elapsed: 66.567955ms
Sep 24 11:22:47.418: INFO: Pod "exec-volume-test-inlinevolume-hvr8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135084776s
Sep 24 11:22:49.487: INFO: Pod "exec-volume-test-inlinevolume-hvr8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.203902479s
Sep 24 11:22:51.556: INFO: Pod "exec-volume-test-inlinevolume-hvr8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.272743379s
Sep 24 11:22:53.625: INFO: Pod "exec-volume-test-inlinevolume-hvr8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.342209937s
Sep 24 11:22:55.695: INFO: Pod "exec-volume-test-inlinevolume-hvr8": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.412177762s
STEP: Saw pod success
Sep 24 11:22:55.695: INFO: Pod "exec-volume-test-inlinevolume-hvr8" satisfied condition "Succeeded or Failed"
Sep 24 11:22:55.763: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod exec-volume-test-inlinevolume-hvr8 container exec-container-inlinevolume-hvr8: <nil>
STEP: delete the pod
Sep 24 11:22:55.909: INFO: Waiting for pod exec-volume-test-inlinevolume-hvr8 to disappear
Sep 24 11:22:55.975: INFO: Pod exec-volume-test-inlinevolume-hvr8 no longer exists
STEP: Deleting pod exec-volume-test-inlinevolume-hvr8
Sep 24 11:22:55.975: INFO: Deleting pod "exec-volume-test-inlinevolume-hvr8" in namespace "volume-387"
Sep 24 11:22:56.187: INFO: Couldn't delete PD "aws://us-west-2a/vol-0652ebd634f63482e", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0652ebd634f63482e is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: fa14fa9b-2bc7-474d-b385-69fa90bb3686
Sep 24 11:23:01.552: INFO: Couldn't delete PD "aws://us-west-2a/vol-0652ebd634f63482e", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0652ebd634f63482e is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: e5c51410-272d-48d6-b0c0-961fed1e8958
Sep 24 11:23:06.972: INFO: Successfully deleted PD "aws://us-west-2a/vol-0652ebd634f63482e".
[AfterEach] [Testpattern: Inline-volume (xfs)][Slow] volumes
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:186
Sep 24 11:23:06.972: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "volume-387" for this suite.
... skipping 30 lines ...
Sep 24 11:23:07.458: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass volume-43958sdht
STEP: creating a claim
Sep 24 11:23:07.526: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod exec-volume-test-dynamicpv-7x6z
STEP: Creating a pod to test exec-volume-test
Sep 24 11:23:07.736: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-7x6z" in namespace "volume-4395" to be "Succeeded or Failed"
Sep 24 11:23:07.807: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 71.277811ms
Sep 24 11:23:09.875: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 2.139025698s
Sep 24 11:23:11.942: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206377209s
Sep 24 11:23:14.010: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 6.2741964s
Sep 24 11:23:16.077: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 8.341427509s
Sep 24 11:23:18.146: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 10.409974174s
Sep 24 11:23:20.214: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 12.477602731s
Sep 24 11:23:22.281: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 14.545425114s
Sep 24 11:23:24.349: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 16.613491084s
Sep 24 11:23:26.417: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 18.680684759s
Sep 24 11:23:28.484: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Pending", Reason="", readiness=false. Elapsed: 20.748006642s
Sep 24 11:23:30.552: INFO: Pod "exec-volume-test-dynamicpv-7x6z": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.816083038s
STEP: Saw pod success
Sep 24 11:23:30.552: INFO: Pod "exec-volume-test-dynamicpv-7x6z" satisfied condition "Succeeded or Failed"
Sep 24 11:23:30.619: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod exec-volume-test-dynamicpv-7x6z container exec-container-dynamicpv-7x6z: <nil>
STEP: delete the pod
Sep 24 11:23:30.764: INFO: Waiting for pod exec-volume-test-dynamicpv-7x6z to disappear
Sep 24 11:23:30.831: INFO: Pod exec-volume-test-dynamicpv-7x6z no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-7x6z
Sep 24 11:23:30.831: INFO: Deleting pod "exec-volume-test-dynamicpv-7x6z" in namespace "volume-4395"
... skipping 360 lines ...
Sep 24 11:23:59.701: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-2116glxbn
STEP: creating a claim
Sep 24 11:23:59.770: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-hx8q
STEP: Creating a pod to test subpath
Sep 24 11:23:59.974: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-hx8q" in namespace "provisioning-2116" to be "Succeeded or Failed"
Sep 24 11:24:00.044: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 69.285489ms
Sep 24 11:24:02.109: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 2.134971118s
Sep 24 11:24:04.175: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 4.200537532s
Sep 24 11:24:06.239: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 6.264859241s
Sep 24 11:24:08.305: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 8.330402014s
Sep 24 11:24:10.370: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 10.396027276s
Sep 24 11:24:12.437: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Pending", Reason="", readiness=false. Elapsed: 12.463188544s
Sep 24 11:24:14.503: INFO: Pod "pod-subpath-test-dynamicpv-hx8q": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.52839973s
STEP: Saw pod success
Sep 24 11:24:14.503: INFO: Pod "pod-subpath-test-dynamicpv-hx8q" satisfied condition "Succeeded or Failed"
Sep 24 11:24:14.566: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-hx8q container test-container-subpath-dynamicpv-hx8q: <nil>
STEP: delete the pod
Sep 24 11:24:14.705: INFO: Waiting for pod pod-subpath-test-dynamicpv-hx8q to disappear
Sep 24 11:24:14.769: INFO: Pod pod-subpath-test-dynamicpv-hx8q no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-hx8q
Sep 24 11:24:14.769: INFO: Deleting pod "pod-subpath-test-dynamicpv-hx8q" in namespace "provisioning-2116"
... skipping 186 lines ...
Sep 24 11:24:14.353: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass volume-1397hwv9h
STEP: creating a claim
Sep 24 11:24:14.422: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod exec-volume-test-dynamicpv-xgkc
STEP: Creating a pod to test exec-volume-test
Sep 24 11:24:14.632: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-xgkc" in namespace "volume-1397" to be "Succeeded or Failed"
Sep 24 11:24:14.700: INFO: Pod "exec-volume-test-dynamicpv-xgkc": Phase="Pending", Reason="", readiness=false. Elapsed: 67.878765ms
Sep 24 11:24:16.768: INFO: Pod "exec-volume-test-dynamicpv-xgkc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135836824s
Sep 24 11:24:18.837: INFO: Pod "exec-volume-test-dynamicpv-xgkc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204827458s
Sep 24 11:24:20.945: INFO: Pod "exec-volume-test-dynamicpv-xgkc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.31253513s
Sep 24 11:24:23.013: INFO: Pod "exec-volume-test-dynamicpv-xgkc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.380818006s
Sep 24 11:24:25.082: INFO: Pod "exec-volume-test-dynamicpv-xgkc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.449625294s
STEP: Saw pod success
Sep 24 11:24:25.082: INFO: Pod "exec-volume-test-dynamicpv-xgkc" satisfied condition "Succeeded or Failed"
Sep 24 11:24:25.149: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod exec-volume-test-dynamicpv-xgkc container exec-container-dynamicpv-xgkc: <nil>
STEP: delete the pod
Sep 24 11:24:25.296: INFO: Waiting for pod exec-volume-test-dynamicpv-xgkc to disappear
Sep 24 11:24:25.364: INFO: Pod exec-volume-test-dynamicpv-xgkc no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-xgkc
Sep 24 11:24:25.364: INFO: Deleting pod "exec-volume-test-dynamicpv-xgkc" in namespace "volume-1397"
... skipping 112 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if non-existent subpath is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:267

      Distro debian doesn't support ntfs -- skipping

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 108 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Inline-volume (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if non-existent subpath is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:267

      Driver supports dynamic provisioning, skipping InlineVolume pattern

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/base.go:244
------------------------------
... skipping 308 lines ...
    [Testpattern: Dynamic PV (ext4)] multiVolume [Slow]
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should access to two volumes with different volume mode and retain data across pod recreation on the same node [It]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:206

      while cleanup resource
      Unexpected error:
          <errors.aggregate | len:1, cap:1>: [
              <errors.aggregate | len:1, cap:1>[
                  <*fmt.wrapError | 0xc000b76400>{
                      msg: "persistent Volume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 not deleted by dynamic provisioner: PersistentVolume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 still exists within 5m0s",
                      err: <*errors.errorString | 0xc0010ae550>{
                          s: "PersistentVolume pvc-9678b70f-5d88-4549-bc83-a70f518963d3 still exists within 5m0s",
... skipping 27 lines ...
Sep 24 11:24:31.460: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-452fx8dr
STEP: creating a claim
Sep 24 11:24:31.524: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-2b9p
STEP: Creating a pod to test atomic-volume-subpath
Sep 24 11:24:31.722: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-2b9p" in namespace "provisioning-452" to be "Succeeded or Failed"
Sep 24 11:24:31.787: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Pending", Reason="", readiness=false. Elapsed: 65.213167ms
Sep 24 11:24:33.852: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Pending", Reason="", readiness=false. Elapsed: 2.129589599s
Sep 24 11:24:35.916: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Pending", Reason="", readiness=false. Elapsed: 4.194176007s
Sep 24 11:24:37.981: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Pending", Reason="", readiness=false. Elapsed: 6.25884409s
Sep 24 11:24:40.059: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Pending", Reason="", readiness=false. Elapsed: 8.337343212s
Sep 24 11:24:42.125: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Pending", Reason="", readiness=false. Elapsed: 10.402733626s
... skipping 7 lines ...
Sep 24 11:24:58.648: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Running", Reason="", readiness=true. Elapsed: 26.926179009s
Sep 24 11:25:00.713: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Running", Reason="", readiness=true. Elapsed: 28.990593067s
Sep 24 11:25:02.777: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Running", Reason="", readiness=true. Elapsed: 31.055020157s
Sep 24 11:25:04.844: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Running", Reason="", readiness=true. Elapsed: 33.121786209s
Sep 24 11:25:06.909: INFO: Pod "pod-subpath-test-dynamicpv-2b9p": Phase="Succeeded", Reason="", readiness=false. Elapsed: 35.186720528s
STEP: Saw pod success
Sep 24 11:25:06.909: INFO: Pod "pod-subpath-test-dynamicpv-2b9p" satisfied condition "Succeeded or Failed"
Sep 24 11:25:06.973: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-2b9p container test-container-subpath-dynamicpv-2b9p: <nil>
STEP: delete the pod
Sep 24 11:25:07.115: INFO: Waiting for pod pod-subpath-test-dynamicpv-2b9p to disappear
Sep 24 11:25:07.179: INFO: Pod pod-subpath-test-dynamicpv-2b9p no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-2b9p
Sep 24 11:25:07.179: INFO: Deleting pod "pod-subpath-test-dynamicpv-2b9p" in namespace "provisioning-452"
... skipping 508 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Inline-volume (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:240

      Driver supports dynamic provisioning, skipping InlineVolume pattern

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/base.go:244
------------------------------
... skipping 10 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:240

      Distro debian doesn't support ntfs -- skipping

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:127
------------------------------
... skipping 480 lines ...
Sep 24 11:26:54.199: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-4710hnw9t
STEP: creating a claim
Sep 24 11:26:54.264: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-6j5x
STEP: Creating a pod to test subpath
Sep 24 11:26:54.461: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-6j5x" in namespace "provisioning-4710" to be "Succeeded or Failed"
Sep 24 11:26:54.526: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 64.514319ms
Sep 24 11:26:56.591: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 2.129520714s
Sep 24 11:26:58.656: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 4.194875066s
Sep 24 11:27:00.723: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 6.261568881s
Sep 24 11:27:02.790: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 8.328264356s
Sep 24 11:27:04.856: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 10.394115098s
Sep 24 11:27:06.921: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.459344238s
STEP: Saw pod success
Sep 24 11:27:06.921: INFO: Pod "pod-subpath-test-dynamicpv-6j5x" satisfied condition "Succeeded or Failed"
Sep 24 11:27:06.997: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-6j5x container test-container-subpath-dynamicpv-6j5x: <nil>
STEP: delete the pod
Sep 24 11:27:07.146: INFO: Waiting for pod pod-subpath-test-dynamicpv-6j5x to disappear
Sep 24 11:27:07.209: INFO: Pod pod-subpath-test-dynamicpv-6j5x no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-6j5x
Sep 24 11:27:07.209: INFO: Deleting pod "pod-subpath-test-dynamicpv-6j5x" in namespace "provisioning-4710"
STEP: Creating pod pod-subpath-test-dynamicpv-6j5x
STEP: Creating a pod to test subpath
Sep 24 11:27:07.344: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-6j5x" in namespace "provisioning-4710" to be "Succeeded or Failed"
Sep 24 11:27:07.409: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 64.406603ms
Sep 24 11:27:09.473: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 2.12855342s
Sep 24 11:27:11.539: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 4.194583701s
Sep 24 11:27:13.604: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 6.260109444s
Sep 24 11:27:15.669: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 8.324865287s
Sep 24 11:27:17.735: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Pending", Reason="", readiness=false. Elapsed: 10.390793854s
Sep 24 11:27:19.800: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Running", Reason="", readiness=true. Elapsed: 12.455899231s
Sep 24 11:27:21.871: INFO: Pod "pod-subpath-test-dynamicpv-6j5x": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.526555795s
STEP: Saw pod success
Sep 24 11:27:21.871: INFO: Pod "pod-subpath-test-dynamicpv-6j5x" satisfied condition "Succeeded or Failed"
Sep 24 11:27:21.935: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-6j5x container test-container-subpath-dynamicpv-6j5x: <nil>
STEP: delete the pod
Sep 24 11:27:22.093: INFO: Waiting for pod pod-subpath-test-dynamicpv-6j5x to disappear
Sep 24 11:27:22.173: INFO: Pod pod-subpath-test-dynamicpv-6j5x no longer exists
STEP: Deleting pod pod-subpath-test-dynamicpv-6j5x
Sep 24 11:27:22.173: INFO: Deleting pod "pod-subpath-test-dynamicpv-6j5x" in namespace "provisioning-4710"
... skipping 259 lines ...

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/capacity.go:78
------------------------------
SS
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode 
  should fail to use a volume in a pod with mismatched mode [Slow]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumemode.go:297

[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:27:37.779: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename volumemode
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail to use a volume in a pod with mismatched mode [Slow]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumemode.go:297
Sep 24 11:27:38.098: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:27:38.098: INFO: Creating resource for dynamic PV
Sep 24 11:27:38.098: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass volumemode-2732mrwlq
STEP: creating a claim
STEP: Creating pod
STEP: Waiting for the pod to fail
Sep 24 11:27:44.560: INFO: Deleting pod "pod-76107af0-82f1-41fd-a385-fdcca4461f21" in namespace "volumemode-2732"
Sep 24 11:27:44.634: INFO: Wait up to 5m0s for pod "pod-76107af0-82f1-41fd-a385-fdcca4461f21" to be fully deleted
STEP: Deleting pvc
Sep 24 11:27:48.898: INFO: Deleting PersistentVolumeClaim "aws479f8"
Sep 24 11:27:48.964: INFO: Waiting up to 5m0s for PersistentVolume pvc-d61d9954-59e7-42cf-a258-0f6e50bea5b2 to get deleted
Sep 24 11:27:49.028: INFO: PersistentVolume pvc-d61d9954-59e7-42cf-a258-0f6e50bea5b2 found and phase=Released (63.956531ms)
... skipping 10 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (filesystem volmode)] volumeMode
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail to use a volume in a pod with mismatched mode [Slow]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/volumemode.go:297
------------------------------
SSSS
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (default fs)] subPath 
  should be able to unmount after the subpath directory is deleted [LinuxOnly]
... skipping 89 lines ...
Sep 24 11:27:55.404: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
STEP: creating a test aws volume
Sep 24 11:27:55.916: INFO: Successfully created a new PD: "aws://us-west-2a/vol-0d860c39d81cc1130".
Sep 24 11:27:55.916: INFO: Creating resource for inline volume
STEP: Creating pod exec-volume-test-inlinevolume-fd9j
STEP: Creating a pod to test exec-volume-test
Sep 24 11:27:55.987: INFO: Waiting up to 5m0s for pod "exec-volume-test-inlinevolume-fd9j" in namespace "volume-2755" to be "Succeeded or Failed"
Sep 24 11:27:56.054: INFO: Pod "exec-volume-test-inlinevolume-fd9j": Phase="Pending", Reason="", readiness=false. Elapsed: 67.534231ms
Sep 24 11:27:58.123: INFO: Pod "exec-volume-test-inlinevolume-fd9j": Phase="Pending", Reason="", readiness=false. Elapsed: 2.136190708s
Sep 24 11:28:00.194: INFO: Pod "exec-volume-test-inlinevolume-fd9j": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207293107s
Sep 24 11:28:02.271: INFO: Pod "exec-volume-test-inlinevolume-fd9j": Phase="Pending", Reason="", readiness=false. Elapsed: 6.284526322s
Sep 24 11:28:04.343: INFO: Pod "exec-volume-test-inlinevolume-fd9j": Phase="Pending", Reason="", readiness=false. Elapsed: 8.356213568s
Sep 24 11:28:06.412: INFO: Pod "exec-volume-test-inlinevolume-fd9j": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.425251838s
STEP: Saw pod success
Sep 24 11:28:06.412: INFO: Pod "exec-volume-test-inlinevolume-fd9j" satisfied condition "Succeeded or Failed"
Sep 24 11:28:06.480: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod exec-volume-test-inlinevolume-fd9j container exec-container-inlinevolume-fd9j: <nil>
STEP: delete the pod
Sep 24 11:28:06.624: INFO: Waiting for pod exec-volume-test-inlinevolume-fd9j to disappear
Sep 24 11:28:06.694: INFO: Pod exec-volume-test-inlinevolume-fd9j no longer exists
STEP: Deleting pod exec-volume-test-inlinevolume-fd9j
Sep 24 11:28:06.694: INFO: Deleting pod "exec-volume-test-inlinevolume-fd9j" in namespace "volume-2755"
Sep 24 11:28:06.907: INFO: Couldn't delete PD "aws://us-west-2a/vol-0d860c39d81cc1130", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0d860c39d81cc1130 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 1dc070f2-4177-4140-9660-aacc46d0483d
Sep 24 11:28:12.294: INFO: Couldn't delete PD "aws://us-west-2a/vol-0d860c39d81cc1130", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0d860c39d81cc1130 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: ff58ff80-c5f9-408d-8543-995154fd6171
Sep 24 11:28:17.684: INFO: Couldn't delete PD "aws://us-west-2a/vol-0d860c39d81cc1130", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0d860c39d81cc1130 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 15f9703e-39cd-4f90-862a-db2a2316df8d
Sep 24 11:28:23.060: INFO: Couldn't delete PD "aws://us-west-2a/vol-0d860c39d81cc1130", sleeping 5s: error deleting EBS volumes: VolumeInUse: Volume vol-0d860c39d81cc1130 is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: e7206b49-ebd6-4c19-84a9-52cfb73710f4
Sep 24 11:28:28.502: INFO: Successfully deleted PD "aws://us-west-2a/vol-0d860c39d81cc1130".
[AfterEach] [Testpattern: Inline-volume (default fs)] volumes
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:186
Sep 24 11:28:28.503: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "volume-2755" for this suite.
... skipping 428 lines ...
Sep 24 11:28:29.299: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-8266jwjlj
STEP: creating a claim
Sep 24 11:28:29.366: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-58s4
STEP: Creating a pod to test multi_subpath
Sep 24 11:28:29.563: INFO: Waiting up to 5m0s for pod "pod-subpath-test-dynamicpv-58s4" in namespace "provisioning-8266" to be "Succeeded or Failed"
Sep 24 11:28:29.627: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 64.275222ms
Sep 24 11:28:31.693: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.129793575s
Sep 24 11:28:33.759: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.195594254s
Sep 24 11:28:35.825: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.261398198s
Sep 24 11:28:37.891: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.327460618s
Sep 24 11:28:39.961: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.398252079s
Sep 24 11:28:42.027: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 12.463336987s
Sep 24 11:28:44.091: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 14.52810929s
Sep 24 11:28:46.157: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 16.593956619s
Sep 24 11:28:48.226: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 18.662433975s
Sep 24 11:28:50.292: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Pending", Reason="", readiness=false. Elapsed: 20.728345927s
Sep 24 11:28:52.357: INFO: Pod "pod-subpath-test-dynamicpv-58s4": Phase="Succeeded", Reason="", readiness=false. Elapsed: 22.793659242s
STEP: Saw pod success
Sep 24 11:28:52.357: INFO: Pod "pod-subpath-test-dynamicpv-58s4" satisfied condition "Succeeded or Failed"
Sep 24 11:28:52.421: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod pod-subpath-test-dynamicpv-58s4 container test-container-subpath-dynamicpv-58s4: <nil>
STEP: delete the pod
Sep 24 11:28:52.565: INFO: Waiting for pod pod-subpath-test-dynamicpv-58s4 to disappear
Sep 24 11:28:52.629: INFO: Pod pod-subpath-test-dynamicpv-58s4 no longer exists
STEP: Deleting pod
Sep 24 11:28:52.629: INFO: Deleting pod "pod-subpath-test-dynamicpv-58s4" in namespace "provisioning-8266"
... skipping 108 lines ...
Sep 24 11:28:55.749: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass volume-9381xtxck
STEP: creating a claim
Sep 24 11:28:55.815: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod exec-volume-test-dynamicpv-mm2j
STEP: Creating a pod to test exec-volume-test
Sep 24 11:28:56.013: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-mm2j" in namespace "volume-9381" to be "Succeeded or Failed"
Sep 24 11:28:56.079: INFO: Pod "exec-volume-test-dynamicpv-mm2j": Phase="Pending", Reason="", readiness=false. Elapsed: 65.698865ms
Sep 24 11:28:58.144: INFO: Pod "exec-volume-test-dynamicpv-mm2j": Phase="Pending", Reason="", readiness=false. Elapsed: 2.130829986s
Sep 24 11:29:00.209: INFO: Pod "exec-volume-test-dynamicpv-mm2j": Phase="Pending", Reason="", readiness=false. Elapsed: 4.196212379s
Sep 24 11:29:02.286: INFO: Pod "exec-volume-test-dynamicpv-mm2j": Phase="Pending", Reason="", readiness=false. Elapsed: 6.273637235s
Sep 24 11:29:04.352: INFO: Pod "exec-volume-test-dynamicpv-mm2j": Phase="Pending", Reason="", readiness=false. Elapsed: 8.338875613s
Sep 24 11:29:06.417: INFO: Pod "exec-volume-test-dynamicpv-mm2j": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.404343683s
STEP: Saw pod success
Sep 24 11:29:06.417: INFO: Pod "exec-volume-test-dynamicpv-mm2j" satisfied condition "Succeeded or Failed"
Sep 24 11:29:06.482: INFO: Trying to get logs from node ip-172-20-49-28.us-west-2.compute.internal pod exec-volume-test-dynamicpv-mm2j container exec-container-dynamicpv-mm2j: <nil>
STEP: delete the pod
Sep 24 11:29:06.620: INFO: Waiting for pod exec-volume-test-dynamicpv-mm2j to disappear
Sep 24 11:29:06.684: INFO: Pod exec-volume-test-dynamicpv-mm2j no longer exists
STEP: Deleting pod exec-volume-test-dynamicpv-mm2j
Sep 24 11:29:06.684: INFO: Deleting pod "exec-volume-test-dynamicpv-mm2j" in namespace "volume-9381"
... skipping 105 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Inline-volume (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly] [BeforeEach]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:278

      Driver supports dynamic provisioning, skipping InlineVolume pattern

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/base.go:244
------------------------------
... skipping 75 lines ...
Sep 24 11:28:29.961: INFO: In creating storage class object and pvc objects for driver - sc: &StorageClass{ObjectMeta:{provisioning-481tnhh7      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Provisioner:kubernetes.io/aws-ebs,Parameters:map[string]string{},ReclaimPolicy:nil,MountOptions:[],AllowVolumeExpansion:nil,VolumeBindingMode:*WaitForFirstConsumer,AllowedTopologies:[]TopologySelectorTerm{},}, pvc: &PersistentVolumeClaim{ObjectMeta:{ pvc- provisioning-481    0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Spec:PersistentVolumeClaimSpec{AccessModes:[ReadWriteOnce],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},},VolumeName:,Selector:nil,StorageClassName:*provisioning-481tnhh7,VolumeMode:nil,DataSource:nil,DataSourceRef:nil,},Status:PersistentVolumeClaimStatus{Phase:,AccessModes:[],Capacity:ResourceList{},Conditions:[]PersistentVolumeClaimCondition{},},}, src-pvc: &PersistentVolumeClaim{ObjectMeta:{ pvc- provisioning-481    0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Spec:PersistentVolumeClaimSpec{AccessModes:[ReadWriteOnce],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},},VolumeName:,Selector:nil,StorageClassName:*provisioning-481tnhh7,VolumeMode:nil,DataSource:nil,DataSourceRef:nil,},Status:PersistentVolumeClaimStatus{Phase:,AccessModes:[],Capacity:ResourceList{},Conditions:[]PersistentVolumeClaimCondition{},},}
STEP: Creating a StorageClass
STEP: creating claim=&PersistentVolumeClaim{ObjectMeta:{ pvc- provisioning-481    0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Spec:PersistentVolumeClaimSpec{AccessModes:[ReadWriteOnce],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},},VolumeName:,Selector:nil,StorageClassName:*provisioning-481tnhh7,VolumeMode:nil,DataSource:nil,DataSourceRef:nil,},Status:PersistentVolumeClaimStatus{Phase:,AccessModes:[],Capacity:ResourceList{},Conditions:[]PersistentVolumeClaimCondition{},},}
STEP: creating a pod referring to the class=&StorageClass{ObjectMeta:{provisioning-481tnhh7    b53ac0a9-d0ca-4e42-bba2-451ec353e5be 6255 0 2022-09-24 11:28:30 +0000 UTC <nil> <nil> map[] map[] [] []  [{e2e-kubernetes.test Update storage.k8s.io/v1 2022-09-24 11:28:30 +0000 UTC FieldsV1 {"f:mountOptions":{},"f:provisioner":{},"f:reclaimPolicy":{},"f:volumeBindingMode":{}} }]},Provisioner:kubernetes.io/aws-ebs,Parameters:map[string]string{},ReclaimPolicy:*Delete,MountOptions:[debug nouid32],AllowVolumeExpansion:nil,VolumeBindingMode:*WaitForFirstConsumer,AllowedTopologies:[]TopologySelectorTerm{},} claim=&PersistentVolumeClaim{ObjectMeta:{pvc-8bwgl pvc- provisioning-481  b7e14a12-3d24-4163-b39b-9f53d7c34b09 6256 0 2022-09-24 11:28:30 +0000 UTC <nil> <nil> map[] map[] [] [kubernetes.io/pvc-protection]  [{e2e-kubernetes.test Update v1 2022-09-24 11:28:30 +0000 UTC FieldsV1 {"f:metadata":{"f:generateName":{}},"f:spec":{"f:accessModes":{},"f:resources":{"f:requests":{".":{},"f:storage":{}}},"f:storageClassName":{},"f:volumeMode":{}},"f:status":{"f:phase":{}}} }]},Spec:PersistentVolumeClaimSpec{AccessModes:[ReadWriteOnce],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},},VolumeName:,Selector:nil,StorageClassName:*provisioning-481tnhh7,VolumeMode:*Filesystem,DataSource:nil,DataSourceRef:nil,},Status:PersistentVolumeClaimStatus{Phase:Pending,AccessModes:[],Capacity:ResourceList{},Conditions:[]PersistentVolumeClaimCondition{},},}
STEP: Deleting pod pod-8ae171d3-878b-4785-a025-dfa31abb3a01 in namespace provisioning-481
STEP: checking the created volume is writable on node {Name: Selector:map[] Affinity:nil}
Sep 24 11:28:52.723: INFO: Waiting up to 15m0s for pod "pvc-volume-tester-writer-jh8g5" in namespace "provisioning-481" to be "Succeeded or Failed"
Sep 24 11:28:52.791: INFO: Pod "pvc-volume-tester-writer-jh8g5": Phase="Pending", Reason="", readiness=false. Elapsed: 67.805968ms
Sep 24 11:28:54.859: INFO: Pod "pvc-volume-tester-writer-jh8g5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135872104s
Sep 24 11:28:56.928: INFO: Pod "pvc-volume-tester-writer-jh8g5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 4.204650736s
STEP: Saw pod success
Sep 24 11:28:56.928: INFO: Pod "pvc-volume-tester-writer-jh8g5" satisfied condition "Succeeded or Failed"
Sep 24 11:28:57.065: INFO: Pod pvc-volume-tester-writer-jh8g5 has the following logs: 
Sep 24 11:28:57.065: INFO: Deleting pod "pvc-volume-tester-writer-jh8g5" in namespace "provisioning-481"
Sep 24 11:28:57.139: INFO: Wait up to 5m0s for pod "pvc-volume-tester-writer-jh8g5" to be fully deleted
STEP: checking the created volume has the correct mount options, is readable and retains data on the same node "ip-172-20-49-28.us-west-2.compute.internal"
Sep 24 11:28:57.415: INFO: Waiting up to 15m0s for pod "pvc-volume-tester-reader-ptgbn" in namespace "provisioning-481" to be "Succeeded or Failed"
Sep 24 11:28:57.482: INFO: Pod "pvc-volume-tester-reader-ptgbn": Phase="Pending", Reason="", readiness=false. Elapsed: 67.055052ms
Sep 24 11:28:59.552: INFO: Pod "pvc-volume-tester-reader-ptgbn": Phase="Pending", Reason="", readiness=false. Elapsed: 2.136371423s
Sep 24 11:29:01.619: INFO: Pod "pvc-volume-tester-reader-ptgbn": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204087958s
Sep 24 11:29:03.690: INFO: Pod "pvc-volume-tester-reader-ptgbn": Phase="Pending", Reason="", readiness=false. Elapsed: 6.275117807s
Sep 24 11:29:05.758: INFO: Pod "pvc-volume-tester-reader-ptgbn": Phase="Pending", Reason="", readiness=false. Elapsed: 8.34308134s
Sep 24 11:29:07.829: INFO: Pod "pvc-volume-tester-reader-ptgbn": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.413805841s
STEP: Saw pod success
Sep 24 11:29:07.829: INFO: Pod "pvc-volume-tester-reader-ptgbn" satisfied condition "Succeeded or Failed"
Sep 24 11:29:07.965: INFO: Pod pvc-volume-tester-reader-ptgbn has the following logs: hello world

Sep 24 11:29:07.966: INFO: Deleting pod "pvc-volume-tester-reader-ptgbn" in namespace "provisioning-481"
Sep 24 11:29:08.040: INFO: Wait up to 5m0s for pod "pvc-volume-tester-reader-ptgbn" to be fully deleted
Sep 24 11:29:08.107: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-8bwgl] to have phase Bound
Sep 24 11:29:08.174: INFO: PersistentVolumeClaim pvc-8bwgl found and phase=Bound (67.197975ms)
... skipping 138 lines ...
Sep 24 11:29:44.563: INFO: Creating resource for dynamic PV
Sep 24 11:29:44.563: INFO: Using claimSize:1Gi, test suite supported size:{ 1Gi}, driver(aws) supported size:{ 1Gi} 
STEP: creating a StorageClass volume-expand-7633m4qxf
STEP: creating a claim
STEP: Expanding non-expandable pvc
Sep 24 11:29:44.780: INFO: currentPvcSize {{1073741824 0} {<nil>} 1Gi BinarySI}, newSize {{2147483648 0} {<nil>}  BinarySI}
Sep 24 11:29:44.927: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:47.064: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:49.065: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:51.065: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:53.065: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:55.066: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:57.063: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:29:59.064: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:01.063: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:03.068: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:05.070: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:07.087: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:09.065: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:11.067: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:13.071: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:15.066: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 5 lines ...
  	},
  	VolumeName:       "",
  	StorageClassName: &"volume-expand-7633m4qxf",
  	... // 2 identical fields
  }

Sep 24 11:30:15.206: INFO: Error updating pvc aws6fv9j: PersistentVolumeClaim "aws6fv9j" is invalid: spec: Forbidden: spec is immutable after creation except resources.requests for bound claims
  core.PersistentVolumeClaimSpec{
  	AccessModes: {"ReadWriteOnce"},
  	Selector:    nil,
  	Resources: core.ResourceRequirements{
  		Limits: nil,
- 		Requests: core.ResourceList{
... skipping 146 lines ...
Sep 24 11:29:34.770: INFO: Creating resource for dynamic PV
Sep 24 11:29:34.770: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-8858r9bf7
STEP: creating a claim
Sep 24 11:29:34.835: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod to format volume volume-prep-provisioning-8858
Sep 24 11:29:35.035: INFO: Waiting up to 5m0s for pod "volume-prep-provisioning-8858" in namespace "provisioning-8858" to be "Succeeded or Failed"
Sep 24 11:29:35.099: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 64.450734ms
Sep 24 11:29:37.166: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 2.131050098s
Sep 24 11:29:39.230: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 4.19563334s
Sep 24 11:29:41.295: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 6.260443137s
Sep 24 11:29:43.361: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 8.326247086s
Sep 24 11:29:45.426: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 10.391519574s
Sep 24 11:29:47.492: INFO: Pod "volume-prep-provisioning-8858": Phase="Pending", Reason="", readiness=false. Elapsed: 12.457560245s
Sep 24 11:29:49.558: INFO: Pod "volume-prep-provisioning-8858": Phase="Succeeded", Reason="", readiness=false. Elapsed: 14.523381206s
STEP: Saw pod success
Sep 24 11:29:49.558: INFO: Pod "volume-prep-provisioning-8858" satisfied condition "Succeeded or Failed"
Sep 24 11:29:49.558: INFO: Deleting pod "volume-prep-provisioning-8858" in namespace "provisioning-8858"
Sep 24 11:29:49.631: INFO: Wait up to 5m0s for pod "volume-prep-provisioning-8858" to be fully deleted
STEP: Creating pod pod-subpath-test-dynamicpv-9xvr
STEP: Checking for subpath error in container status
Sep 24 11:29:55.891: INFO: Deleting pod "pod-subpath-test-dynamicpv-9xvr" in namespace "provisioning-8858"
Sep 24 11:29:55.979: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-9xvr" to be fully deleted
STEP: Deleting pod
Sep 24 11:29:56.044: INFO: Deleting pod "pod-subpath-test-dynamicpv-9xvr" in namespace "provisioning-8858"
STEP: Deleting pvc
Sep 24 11:29:56.241: INFO: Deleting PersistentVolumeClaim "awsz4rtl"
... skipping 218 lines ...

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/base.go:244
------------------------------
S
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (delayed binding)] topology 
  should fail to schedule a pod which has topologies that conflict with AllowedTopologies
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/topology.go:192

[BeforeEach] [Testpattern: Dynamic PV (delayed binding)] topology
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (delayed binding)] topology
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:30:28.523: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename topology
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail to schedule a pod which has topologies that conflict with AllowedTopologies
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/topology.go:192
Sep 24 11:30:28.909: INFO: found topology map[topology.kubernetes.io/zone:us-west-2c]
Sep 24 11:30:28.909: INFO: found topology map[topology.kubernetes.io/zone:us-west-2a]
Sep 24 11:30:28.909: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:30:28.909: INFO: Creating storage class object and pvc object for driver - sc: &StorageClass{ObjectMeta:{topology-3267zpg44      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Provisioner:kubernetes.io/aws-ebs,Parameters:map[string]string{},ReclaimPolicy:nil,MountOptions:[],AllowVolumeExpansion:nil,VolumeBindingMode:*WaitForFirstConsumer,AllowedTopologies:[]TopologySelectorTerm{{[{topology.kubernetes.io/zone [us-west-2c]}]},},}, pvc: &PersistentVolumeClaim{ObjectMeta:{ pvc- topology-3267    0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] []  []},Spec:PersistentVolumeClaimSpec{AccessModes:[ReadWriteOnce],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},},VolumeName:,Selector:nil,StorageClassName:*topology-3267zpg44,VolumeMode:nil,DataSource:nil,DataSourceRef:nil,},Status:PersistentVolumeClaimStatus{Phase:,AccessModes:[],Capacity:ResourceList{},Conditions:[]PersistentVolumeClaimCondition{},},}
STEP: Creating sc
... skipping 79 lines ...

      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:386
------------------------------
SSSS
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if non-existent subpath is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:267

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:30:17.066: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename provisioning
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail if non-existent subpath is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:267
Sep 24 11:30:17.405: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:30:17.405: INFO: Creating resource for dynamic PV
Sep 24 11:30:17.405: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-62849972z
STEP: creating a claim
Sep 24 11:30:17.473: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-t4gl
STEP: Checking for subpath error in container status
Sep 24 11:30:31.819: INFO: Deleting pod "pod-subpath-test-dynamicpv-t4gl" in namespace "provisioning-6284"
Sep 24 11:30:31.889: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-t4gl" to be fully deleted
STEP: Deleting pod
Sep 24 11:30:38.034: INFO: Deleting pod "pod-subpath-test-dynamicpv-t4gl" in namespace "provisioning-6284"
STEP: Deleting pvc
Sep 24 11:30:38.241: INFO: Deleting PersistentVolumeClaim "aws4dbch"
... skipping 11 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if non-existent subpath is outside the volume [Slow][LinuxOnly]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:267
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (default fs)] subPath 
  should support restarting containers using directory as subpath [Slow]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:320

... skipping 513 lines ...
      (Always)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208
------------------------------
SS
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (default fs)] subPath 
  should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:278

[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:51
[BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/framework/framework.go:185
STEP: Creating a kubernetes client
Sep 24 11:31:33.925: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-18977.k8s.local.kops.kubeconfig
STEP: Building a namespace api object, basename provisioning
STEP: Waiting for a default service account to be provisioned in namespace
[It] should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]
  /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:278
Sep 24 11:31:34.262: INFO: In-tree plugin kubernetes.io/aws-ebs is not migrated, not validating any metrics
Sep 24 11:31:34.262: INFO: Creating resource for dynamic PV
Sep 24 11:31:34.262: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(aws) supported size:{ 1Mi} 
STEP: creating a StorageClass provisioning-9741747lp
STEP: creating a claim
Sep 24 11:31:34.330: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil
STEP: Creating pod pod-subpath-test-dynamicpv-rkpk
STEP: Checking for subpath error in container status
Sep 24 11:31:52.678: INFO: Deleting pod "pod-subpath-test-dynamicpv-rkpk" in namespace "provisioning-9741"
Sep 24 11:31:52.747: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-rkpk" to be fully deleted
STEP: Deleting pod
Sep 24 11:31:58.884: INFO: Deleting pod "pod-subpath-test-dynamicpv-rkpk" in namespace "provisioning-9741"
STEP: Deleting pvc
Sep 24 11:31:59.087: INFO: Deleting PersistentVolumeClaim "awsccp9g"
... skipping 11 lines ...
[ebs-csi-migration] EBS CSI Migration
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:85
  [Driver: aws]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:91
    [Testpattern: Dynamic PV (default fs)] subPath
    /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/framework/testsuite.go:50
      should fail if subpath with backstepping is outside the volume [Slow][LinuxOnly]
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/subpath.go:278
------------------------------
SSSSS
------------------------------
[ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] 
  should concurrently access the single read-only volume from pods on the same node
... skipping 256 lines ...
      /home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:135
------------------------------


Summarizing 1 Failure:

[Fail] [ebs-csi-migration] EBS CSI Migration [Driver: aws] [Testpattern: Dynamic PV (ext4)] multiVolume [Slow] [It] should access to two volumes with different volume mode and retain data across pod recreation on the same node 
/home/prow/go/pkg/mod/k8s.io/kubernetes@v1.22.11/test/e2e/storage/testsuites/multivolume.go:126

Ran 66 of 539 Specs in 947.170 seconds
FAIL! -- 65 Passed | 1 Failed | 0 Pending | 473 Skipped


Ginkgo ran 1 suite in 17m12.562103234s
Test Suite Failed
+ TEST_PASSED=1
+ set -e
+ set +x
###
## TEST_PASSED: 1
#
... skipping 32 lines ...
#
0
###
## MIGRATION_PASSED: 0
#
###
## One of test or migration failed
#
###
## Printing pod ebs-csi-controller-8b575b4db-dhpwb ebs-plugin container logs
#
I0924 11:15:18.795085       1 driver.go:73] Driver: ebs.csi.aws.com Version: v1.11.3
I0924 11:15:18.795132       1 controller.go:81] [Debug] Retrieving region from metadata service
... skipping 151 lines ...
I0924 11:17:52.979683       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-065243f2759199bac Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:17:53.120395       1 inflight.go:74] Node Service: volume="vol-065243f2759199bac" operation finished
I0924 11:17:54.389943       1 cloud.go:665] Waiting for volume "vol-05820b028ab17694e" state: actual=detaching, desired=detached
I0924 11:17:54.497571       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0fccd84921e2dae76 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:17:54.517964       1 cloud.go:665] Waiting for volume "vol-0d66d711decc4538e" state: actual=detaching, desired=detached
I0924 11:17:55.201629       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbd -> volume vol-0fccd84921e2dae76
E0924 11:17:55.201665       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0fccd84921e2dae76" to node "i-0efded25a41d8b33d": could not attach volume "vol-0fccd84921e2dae76" to node "i-0efded25a41d8b33d": IncorrectState: vol-0fccd84921e2dae76 is not 'available'.
	status code: 400, request id: 4bb658ac-c741-4b8b-9918-c87d021ea4ce
I0924 11:17:55.207853       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0fccd84921e2dae76 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:17:55.772577       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbc -> volume vol-0fccd84921e2dae76
E0924 11:17:55.772604       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0fccd84921e2dae76" to node "i-0efded25a41d8b33d": could not attach volume "vol-0fccd84921e2dae76" to node "i-0efded25a41d8b33d": IncorrectState: vol-0fccd84921e2dae76 is not 'available'.
	status code: 400, request id: 35335ef2-c5b2-4b5f-8593-0f47369df8dc
I0924 11:17:56.208688       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0fccd84921e2dae76 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:17:56.811268       1 cloud.go:492] [Debug] AttachVolume volume="vol-0fccd84921e2dae76" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:17:56.789 +0000 UTC,
  Device: "/dev/xvdbc",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-0fccd84921e2dae76"
}
I0924 11:17:56.870702       1 cloud.go:665] Waiting for volume "vol-0fccd84921e2dae76" state: actual=attaching, desired=attached
E0924 11:17:57.695101       1 manager.go:44] Error releasing device: release on device "/dev/xvdbc" assigned to different volume: "vol-05820b028ab17694e" vs "vol-0fccd84921e2dae76"
I0924 11:17:57.695121       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-05820b028ab17694e detached from node i-0efded25a41d8b33d
I0924 11:17:57.709950       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-05820b028ab17694e NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:17:57.751032       1 cloud.go:539] DetachDisk called on non-attached volume: vol-05820b028ab17694e
I0924 11:17:57.838096       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0d66d711decc4538e detached from node i-0efded25a41d8b33d
I0924 11:17:57.938415       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbc -> volume vol-0fccd84921e2dae76
I0924 11:17:57.938431       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0fccd84921e2dae76 attached to node i-0efded25a41d8b33d through device /dev/xvdbc
... skipping 226 lines ...
  State: "attaching",
  VolumeId: "vol-0ba376f8d79bfb2d1"
}
I0924 11:19:16.372090       1 cloud.go:665] Waiting for volume "vol-0ba376f8d79bfb2d1" state: actual=attaching, desired=attached
I0924 11:19:17.430769       1 cloud.go:665] Waiting for volume "vol-0ba376f8d79bfb2d1" state: actual=attaching, desired=attached
I0924 11:19:17.984817       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0b6e4825ea5718ebf detached from node i-0efded25a41d8b33d
E0924 11:19:17.992638       1 manager.go:44] Error releasing device: release on device "/dev/xvdba" assigned to different volume: "vol-02d2e9b92fbb3f4a5" vs "vol-0ba376f8d79bfb2d1"
I0924 11:19:17.992659       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-02d2e9b92fbb3f4a5 detached from node i-0efded25a41d8b33d
I0924 11:19:18.004653       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-0b6e4825ea5718ebf NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:19:18.047176       1 cloud.go:539] DetachDisk called on non-attached volume: vol-0b6e4825ea5718ebf
I0924 11:19:18.182172       1 cloud.go:665] Waiting for volume "vol-0c732fbcb741ea9f0" state: actual=detaching, desired=detached
I0924 11:19:19.289927       1 cloud.go:665] Waiting for volume "vol-0ba376f8d79bfb2d1" state: actual=attaching, desired=attached
I0924 11:19:22.590431       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-0ba376f8d79bfb2d1
... skipping 118 lines ...
W0924 11:20:18.006739       1 cloud.go:539] DetachDisk called on non-attached volume: vol-07b62bc3c05f841cf
I0924 11:20:21.380959       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-06ac2855b3aeb9ece NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:21.384503       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-022e9476b5b1e4a61 NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:21.760345       1 cloud.go:665] Waiting for volume "vol-022e9476b5b1e4a61" state: actual=detaching, desired=detached
I0924 11:20:21.847144       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:21.919960       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:20:21.919990       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 715f0507-28de-4995-b690-453627b87a90
I0924 11:20:22.867166       1 cloud.go:665] Waiting for volume "vol-022e9476b5b1e4a61" state: actual=detaching, desired=detached
I0924 11:20:22.921721       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:22.992110       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:20:22.992128       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 63c7c460-d8b0-416d-97a7-60be64677ad5
I0924 11:20:23.498481       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-07b62bc3c05f841cf Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:23.631363       1 inflight.go:74] Node Service: volume="vol-07b62bc3c05f841cf" operation finished
I0924 11:20:24.732572       1 cloud.go:665] Waiting for volume "vol-022e9476b5b1e4a61" state: actual=detaching, desired=detached
I0924 11:20:24.987739       1 controller.go:103] CreateVolume: called with args {Name:pvc-e526216e-304d-4fb6-b974-e2a1eabf81e7 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-e526216e-304d-4fb6-b974-e2a1eabf81e7 csi.storage.k8s.io/pvc/name:awst89k9 csi.storage.k8s.io/pvc/namespace:provisioning-9251] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:24.993071       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:25.075469       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:20:25.075485       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 7ab3895b-8586-4610-a7cd-05f338fe4854
I0924 11:20:26.402149       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-08863a940cb186b24 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:26.571404       1 inflight.go:74] Node Service: volume="vol-08863a940cb186b24" operation finished
I0924 11:20:28.037401       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-022e9476b5b1e4a61 detached from node i-0efded25a41d8b33d
I0924 11:20:28.302867       1 inflight.go:74] Node Service: volume="pvc-e526216e-304d-4fb6-b974-e2a1eabf81e7" operation finished
I0924 11:20:29.076339       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:29.101057       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-063fbe641c2be4b08 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:29.148449       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:20:29.148462       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: e6b73fb4-73a9-4c17-8999-afb8d09915cb
I0924 11:20:29.669493       1 cloud.go:492] [Debug] AttachVolume volume="vol-063fbe641c2be4b08" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:20:29.65 +0000 UTC,
  Device: "/dev/xvdbb",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-063fbe641c2be4b08"
}
I0924 11:20:29.738191       1 cloud.go:665] Waiting for volume "vol-063fbe641c2be4b08" state: actual=attaching, desired=attached
I0924 11:20:30.804966       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-063fbe641c2be4b08
I0924 11:20:30.804983       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-063fbe641c2be4b08 attached to node i-0efded25a41d8b33d through device /dev/xvdbb
I0924 11:20:32.708024       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0e7756ae5396adbb5 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:33.265546       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbc -> volume vol-0e7756ae5396adbb5
E0924 11:20:33.265568       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0e7756ae5396adbb5" to node "i-0efded25a41d8b33d": could not attach volume "vol-0e7756ae5396adbb5" to node "i-0efded25a41d8b33d": IncorrectState: vol-0e7756ae5396adbb5 is not 'available'.
	status code: 400, request id: 984814de-f4e5-46ca-96f2-34572c199915
I0924 11:20:33.271922       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0e7756ae5396adbb5 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:33.769067       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbc -> volume vol-0e7756ae5396adbb5
E0924 11:20:33.769105       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0e7756ae5396adbb5" to node "i-0efded25a41d8b33d": could not attach volume "vol-0e7756ae5396adbb5" to node "i-0efded25a41d8b33d": IncorrectState: vol-0e7756ae5396adbb5 is not 'available'.
	status code: 400, request id: e73018b6-8d30-465a-821e-0fa44e84e599
I0924 11:20:34.271758       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0e7756ae5396adbb5 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:34.787054       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbc -> volume vol-0e7756ae5396adbb5
E0924 11:20:34.787078       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0e7756ae5396adbb5" to node "i-0efded25a41d8b33d": could not attach volume "vol-0e7756ae5396adbb5" to node "i-0efded25a41d8b33d": IncorrectState: vol-0e7756ae5396adbb5 is not 'available'.
	status code: 400, request id: 7f2a2fc3-881c-416a-b6a8-3134c4a3eda4
I0924 11:20:37.149415       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:37.225715       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:20:37.225730       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 693e8fd6-d5bc-428c-ac07-f27d929a65a5
I0924 11:20:38.797900       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0e7756ae5396adbb5 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:39.395339       1 cloud.go:492] [Debug] AttachVolume volume="vol-0e7756ae5396adbb5" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:20:39.377 +0000 UTC,
  Device: "/dev/xvdbc",
  InstanceId: "i-0efded25a41d8b33d",
... skipping 13 lines ...
I0924 11:20:47.950771       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-063fbe641c2be4b08 NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:20:47.987816       1 cloud.go:539] DetachDisk called on non-attached volume: vol-063fbe641c2be4b08
I0924 11:20:48.581921       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-063fbe641c2be4b08 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:48.743040       1 inflight.go:74] Node Service: volume="vol-063fbe641c2be4b08" operation finished
I0924 11:20:53.227023       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:53.297400       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:20:53.297415       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 3c2c6a63-80b5-4c81-82c6-77e7146975e8
I0924 11:21:11.332404       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-0ba376f8d79bfb2d1 NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:11.786623       1 cloud.go:665] Waiting for volume "vol-0ba376f8d79bfb2d1" state: actual=detaching, desired=detached
I0924 11:21:12.848453       1 cloud.go:665] Waiting for volume "vol-0ba376f8d79bfb2d1" state: actual=detaching, desired=detached
I0924 11:21:14.715703       1 cloud.go:665] Waiting for volume "vol-0ba376f8d79bfb2d1" state: actual=detaching, desired=detached
I0924 11:21:18.019757       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0ba376f8d79bfb2d1 detached from node i-0efded25a41d8b33d
I0924 11:21:21.072687       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0ba376f8d79bfb2d1 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:21.204198       1 inflight.go:74] Node Service: volume="vol-0ba376f8d79bfb2d1" operation finished
I0924 11:21:22.640667       1 controller.go:103] CreateVolume: called with args {Name:pvc-81160c4b-31da-492d-8587-1d88251534fa CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-81160c4b-31da-492d-8587-1d88251534fa csi.storage.k8s.io/pvc/name:awssvsv8 csi.storage.k8s.io/pvc/namespace:provisioning-6926] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:24.720812       1 controller.go:103] CreateVolume: called with args {Name:pvc-0df90876-8994-463e-aed5-03c6cd1edd5c CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-0df90876-8994-463e-aed5-03c6cd1edd5c csi.storage.k8s.io/pvc/name:aws954js csi.storage.k8s.io/pvc/namespace:provisioning-1189] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:25.299018       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:25.374229       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:21:25.374245       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: f112c9f2-dc10-49bb-add4-0f798bc5442e
I0924 11:21:25.966431       1 inflight.go:74] Node Service: volume="pvc-81160c4b-31da-492d-8587-1d88251534fa" operation finished
I0924 11:21:26.678048       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-005902afd6d91e584 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:27.307076       1 cloud.go:492] [Debug] AttachVolume volume="vol-005902afd6d91e584" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:21:27.286 +0000 UTC,
  Device: "/dev/xvdba",
... skipping 52 lines ...
}
I0924 11:21:43.063377       1 cloud.go:665] Waiting for volume "vol-06e21999aabb2e0dc" state: actual=attaching, desired=attached
I0924 11:21:44.127499       1 cloud.go:665] Waiting for volume "vol-06e21999aabb2e0dc" state: actual=attaching, desired=attached
I0924 11:21:44.710229       1 cloud.go:665] Waiting for volume "vol-005902afd6d91e584" state: actual=detaching, desired=detached
I0924 11:21:44.856830       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0d62c0609c121aadb Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:44.932935       1 inflight.go:74] Node Service: volume="vol-0d62c0609c121aadb" operation finished
E0924 11:21:44.932952       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-0d62c0609c121aadb": DeleteDisk could not delete volume: VolumeInUse: Volume vol-0d62c0609c121aadb is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 41cbb7c2-bc21-46bd-bcd2-ff824f63a946
I0924 11:21:45.997678       1 cloud.go:665] Waiting for volume "vol-06e21999aabb2e0dc" state: actual=attaching, desired=attached
I0924 11:21:48.030578       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-005902afd6d91e584 detached from node i-0efded25a41d8b33d
I0924 11:21:49.303534       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbc -> volume vol-06e21999aabb2e0dc
I0924 11:21:49.303552       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-06e21999aabb2e0dc attached to node i-0efded25a41d8b33d through device /dev/xvdbc
I0924 11:21:52.933929       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0d62c0609c121aadb Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:53.054256       1 inflight.go:74] Node Service: volume="vol-0d62c0609c121aadb" operation finished
I0924 11:21:54.871993       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-005902afd6d91e584 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:54.997676       1 inflight.go:74] Node Service: volume="vol-005902afd6d91e584" operation finished
I0924 11:21:56.406796       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-00859d2979014837a NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:56.920427       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-00859d2979014837a
E0924 11:21:56.920504       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-00859d2979014837a" to node "i-0efded25a41d8b33d": could not attach volume "vol-00859d2979014837a" to node "i-0efded25a41d8b33d": IncorrectState: vol-00859d2979014837a is not 'available'.
	status code: 400, request id: 64bc0778-f547-4069-8a4c-d9330a521769
I0924 11:21:56.927571       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-00859d2979014837a NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:57.449659       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-00859d2979014837a
E0924 11:21:57.449680       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-00859d2979014837a" to node "i-0efded25a41d8b33d": could not attach volume "vol-00859d2979014837a" to node "i-0efded25a41d8b33d": IncorrectState: vol-00859d2979014837a is not 'available'.
	status code: 400, request id: acb9cade-d521-4c3d-af97-9c9127bfcefd
I0924 11:21:57.928607       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-00859d2979014837a NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:58.475023       1 cloud.go:492] [Debug] AttachVolume volume="vol-00859d2979014837a" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:21:58.455 +0000 UTC,
  Device: "/dev/xvdba",
  InstanceId: "i-0efded25a41d8b33d",
... skipping 35 lines ...
I0924 11:22:21.255833       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-06e21999aabb2e0dc
I0924 11:22:21.255852       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-06e21999aabb2e0dc attached to node i-0efded25a41d8b33d through device /dev/xvdbb
I0924 11:22:21.265496       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-06e21999aabb2e0dc NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:21.505870       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-06e21999aabb2e0dc attached to node i-0efded25a41d8b33d through device /dev/xvdbb
I0924 11:22:29.375308       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:29.448275       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:22:29.448303       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: be9b64f1-d317-4bb2-a610-d9735d3fedcb
I0924 11:22:31.443982       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-06e21999aabb2e0dc NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:31.449282       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-00859d2979014837a NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:31.897318       1 cloud.go:665] Waiting for volume "vol-06e21999aabb2e0dc" state: actual=detaching, desired=detached
I0924 11:22:32.065630       1 cloud.go:665] Waiting for volume "vol-00859d2979014837a" state: actual=detaching, desired=detached
I0924 11:22:32.972927       1 cloud.go:665] Waiting for volume "vol-06e21999aabb2e0dc" state: actual=detaching, desired=detached
... skipping 27 lines ...
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-0df6b26f9b844f38e"
}
I0924 11:22:45.797808       1 cloud.go:665] Waiting for volume "vol-0df6b26f9b844f38e" state: actual=attaching, desired=attached
I0924 11:22:45.855167       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-0652ebd634f63482e
E0924 11:22:45.855189       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0652ebd634f63482e" to node "i-0efded25a41d8b33d": could not attach volume "vol-0652ebd634f63482e" to node "i-0efded25a41d8b33d": IncorrectState: vol-0652ebd634f63482e is not 'available'.
	status code: 400, request id: f395e06f-b33c-4190-93f4-e54e142d91bd
I0924 11:22:45.861300       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0652ebd634f63482e NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:46.482568       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-0652ebd634f63482e
E0924 11:22:46.482652       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0652ebd634f63482e" to node "i-0efded25a41d8b33d": could not attach volume "vol-0652ebd634f63482e" to node "i-0efded25a41d8b33d": IncorrectState: vol-0652ebd634f63482e is not 'available'.
	status code: 400, request id: 02273e61-3d95-426d-9f19-d83039d65e48
I0924 11:22:46.861240       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0652ebd634f63482e NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:46.865733       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-0df6b26f9b844f38e
I0924 11:22:46.865790       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0df6b26f9b844f38e attached to node i-0efded25a41d8b33d through device /dev/xvdba
I0924 11:22:46.871489       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0df6b26f9b844f38e NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:47.129058       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0df6b26f9b844f38e attached to node i-0efded25a41d8b33d through device /dev/xvdba
... skipping 118 lines ...
  Device: "/dev/xvdbb",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-0ee0e03173c33afa6"
}
I0924 11:24:04.683626       1 cloud.go:665] Waiting for volume "vol-0ee0e03173c33afa6" state: actual=attaching, desired=attached
E0924 11:24:04.736524       1 manager.go:44] Error releasing device: release on device "/dev/xvdbb" assigned to different volume: "vol-00ce52d7e0ba1461e" vs "vol-0ee0e03173c33afa6"
I0924 11:24:04.736544       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-00ce52d7e0ba1461e detached from node i-0efded25a41d8b33d
I0924 11:24:04.772133       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-00ce52d7e0ba1461e NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:24:04.809581       1 cloud.go:539] DetachDisk called on non-attached volume: vol-00ce52d7e0ba1461e
I0924 11:24:05.745462       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-0ee0e03173c33afa6
I0924 11:24:05.745483       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0ee0e03173c33afa6 attached to node i-0efded25a41d8b33d through device /dev/xvdbb
I0924 11:24:05.753737       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0ee0e03173c33afa6 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
... skipping 43 lines ...
  VolumeId: "vol-0b81e1a6029f414da"
}
I0924 11:24:36.560555       1 cloud.go:665] Waiting for volume "vol-0b81e1a6029f414da" state: actual=attaching, desired=attached
I0924 11:24:36.663203       1 controller.go:103] CreateVolume: called with args {Name:pvc-1cada149-0acf-480e-9968-c5b3b9cbab70 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-1cada149-0acf-480e-9968-c5b3b9cbab70 csi.storage.k8s.io/pvc/name:aws2qf4s csi.storage.k8s.io/pvc/namespace:volume-8636] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:24:37.449410       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:24:37.520771       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:24:37.520788       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: e685bde8-711e-4cb0-846e-774c5bc77146
I0924 11:24:37.629643       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-0b81e1a6029f414da
I0924 11:24:37.629662       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0b81e1a6029f414da attached to node i-0efded25a41d8b33d through device /dev/xvdba
I0924 11:24:38.109125       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-05d9373451e375e36 detached from node i-0efded25a41d8b33d
I0924 11:24:39.961011       1 inflight.go:74] Node Service: volume="pvc-1cada149-0acf-480e-9968-c5b3b9cbab70" operation finished
I0924 11:24:40.640706       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05d9373451e375e36 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
... skipping 329 lines ...
  Device: "/dev/xvdbb",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-01d19b7f1f2cf70fc"
}
I0924 11:27:08.640144       1 cloud.go:665] Waiting for volume "vol-01d19b7f1f2cf70fc" state: actual=attaching, desired=attached
E0924 11:27:08.910149       1 manager.go:44] Error releasing device: release on device "/dev/xvdbb" assigned to different volume: "vol-08956cd6b337b35d4" vs "vol-01d19b7f1f2cf70fc"
I0924 11:27:08.910169       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-08956cd6b337b35d4 detached from node i-0efded25a41d8b33d
I0924 11:27:08.948954       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-08956cd6b337b35d4 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:08.950483       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-08c6c06c483ec010a NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:09.516503       1 cloud.go:492] [Debug] AttachVolume volume="vol-08956cd6b337b35d4" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:27:09.493 +0000 UTC,
  Device: "/dev/xvdbd",
... skipping 117 lines ...
I0924 11:27:54.736489       1 inflight.go:74] Node Service: volume="vol-01d19b7f1f2cf70fc" operation finished
I0924 11:27:55.583053       1 controller.go:103] CreateVolume: called with args {Name:pvc-57cb9b7a-7704-4680-9450-3dbd97518c0e CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-57cb9b7a-7704-4680-9450-3dbd97518c0e csi.storage.k8s.io/pvc/name:awsgm9vd csi.storage.k8s.io/pvc/namespace:volume-67] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:55.987141       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0d860c39d81cc1130 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:55.989866       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0330e2a68a76a73cf Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:56.126857       1 inflight.go:74] Node Service: volume="vol-0330e2a68a76a73cf" operation finished
I0924 11:27:56.495937       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-0d860c39d81cc1130
E0924 11:27:56.495981       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0d860c39d81cc1130" to node "i-0efded25a41d8b33d": could not attach volume "vol-0d860c39d81cc1130" to node "i-0efded25a41d8b33d": IncorrectState: vol-0d860c39d81cc1130 is not 'available'.
	status code: 400, request id: 7477d3d3-bf71-4284-a8c5-6cca0f7eafee
I0924 11:27:56.504670       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0d860c39d81cc1130 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:57.041023       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-0d860c39d81cc1130
E0924 11:27:57.041048       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0d860c39d81cc1130" to node "i-0efded25a41d8b33d": could not attach volume "vol-0d860c39d81cc1130" to node "i-0efded25a41d8b33d": IncorrectState: vol-0d860c39d81cc1130 is not 'available'.
	status code: 400, request id: 8bf7de07-b305-4f7b-8712-94124d5749cc
I0924 11:27:57.504682       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0d860c39d81cc1130 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:27:58.073907       1 cloud.go:492] [Debug] AttachVolume volume="vol-0d860c39d81cc1130" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:27:58.05 +0000 UTC,
  Device: "/dev/xvdba",
  InstanceId: "i-0efded25a41d8b33d",
... skipping 106 lines ...
I0924 11:28:42.902661       1 cloud.go:665] Waiting for volume "vol-0f29e4ac6bc1c47d6" state: actual=detaching, desired=detached
I0924 11:28:43.960383       1 cloud.go:665] Waiting for volume "vol-0f29e4ac6bc1c47d6" state: actual=detaching, desired=detached
I0924 11:28:44.854092       1 controller.go:103] CreateVolume: called with args {Name:pvc-95be6e07-6fd5-4496-bc79-3bff8990ebe2 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-95be6e07-6fd5-4496-bc79-3bff8990ebe2 csi.storage.k8s.io/pvc/name:awsv84hx csi.storage.k8s.io/pvc/namespace:provisioning-3952] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:28:45.845573       1 cloud.go:665] Waiting for volume "vol-0f29e4ac6bc1c47d6" state: actual=detaching, desired=detached
I0924 11:28:48.189196       1 inflight.go:74] Node Service: volume="pvc-95be6e07-6fd5-4496-bc79-3bff8990ebe2" operation finished
I0924 11:28:48.944423       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-05212e2c085ee10d7 NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
E0924 11:28:49.143241       1 manager.go:44] Error releasing device: release on device "/dev/xvdbb" assigned to different volume: "vol-0f29e4ac6bc1c47d6" vs "vol-05212e2c085ee10d7"
I0924 11:28:49.143265       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0f29e4ac6bc1c47d6 detached from node i-0efded25a41d8b33d
I0924 11:28:49.538600       1 cloud.go:492] [Debug] AttachVolume volume="vol-05212e2c085ee10d7" instance="i-0efded25a41d8b33d" request returned {
  AttachTime: 2022-09-24 11:28:49.513 +0000 UTC,
  Device: "/dev/xvdbb",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
... skipping 3 lines ...
I0924 11:28:50.662433       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-05212e2c085ee10d7
I0924 11:28:50.662453       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-05212e2c085ee10d7 attached to node i-0efded25a41d8b33d through device /dev/xvdbb
I0924 11:28:52.576375       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-0778d4932b684d179 NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:28:52.980154       1 cloud.go:665] Waiting for volume "vol-0778d4932b684d179" state: actual=detaching, desired=detached
I0924 11:28:53.522485       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-06ac2855b3aeb9ece Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:28:53.588387       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:28:53.588465       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 900d97f6-f7f2-44cc-ad9c-75090cc6c0c1
I0924 11:28:53.943877       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0f29e4ac6bc1c47d6 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:28:54.063346       1 cloud.go:665] Waiting for volume "vol-0778d4932b684d179" state: actual=detaching, desired=detached
I0924 11:28:54.074399       1 inflight.go:74] Node Service: volume="vol-0f29e4ac6bc1c47d6" operation finished
I0924 11:28:55.921003       1 cloud.go:665] Waiting for volume "vol-0778d4932b684d179" state: actual=detaching, desired=detached
I0924 11:28:56.002304       1 controller.go:103] CreateVolume: called with args {Name:pvc-00bc5e43-1c6d-4067-81ab-4d64fe9bc8a4 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-00bc5e43-1c6d-4067-81ab-4d64fe9bc8a4 csi.storage.k8s.io/pvc/name:awstlht9 csi.storage.k8s.io/pvc/namespace:volume-9381] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
... skipping 132 lines ...
  Device: "/dev/xvdbd",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-007e2682259859de5"
}
I0924 11:30:22.562314       1 inflight.go:74] Node Service: volume="vol-06ac2855b3aeb9ece" operation finished
E0924 11:30:22.562331       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-06ac2855b3aeb9ece": DeleteDisk could not delete volume: VolumeInUse: Volume vol-06ac2855b3aeb9ece is currently attached to i-0efded25a41d8b33d
	status code: 400, request id: 20ead53d-e5c1-4fd4-9b42-8777d84eedc4
I0924 11:30:22.582187       1 cloud.go:665] Waiting for volume "vol-007e2682259859de5" state: actual=attaching, desired=attached
I0924 11:30:22.625857       1 inflight.go:74] Node Service: volume="vol-0bdc8969545d0272a" operation finished
I0924 11:30:23.653364       1 cloud.go:665] Waiting for volume "vol-007e2682259859de5" state: actual=attaching, desired=attached
I0924 11:30:25.520591       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbd -> volume vol-007e2682259859de5
I0924 11:30:25.520610       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-007e2682259859de5 attached to node i-0efded25a41d8b33d through device /dev/xvdbd
... skipping 35 lines ...
  Device: "/dev/xvdbb",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-03c016c49f4f2e32b"
}
I0924 11:30:48.997785       1 cloud.go:665] Waiting for volume "vol-03c016c49f4f2e32b" state: actual=attaching, desired=attached
E0924 11:30:49.934802       1 manager.go:44] Error releasing device: release on device "/dev/xvdbb" assigned to different volume: "vol-05212e2c085ee10d7" vs "vol-03c016c49f4f2e32b"
I0924 11:30:49.934825       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-05212e2c085ee10d7 detached from node i-0efded25a41d8b33d
I0924 11:30:49.947906       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-05212e2c085ee10d7 NodeId:i-0efded25a41d8b33d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:30:49.986912       1 cloud.go:539] DetachDisk called on non-attached volume: vol-05212e2c085ee10d7
I0924 11:30:50.075841       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-03c016c49f4f2e32b
I0924 11:30:50.075861       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-03c016c49f4f2e32b attached to node i-0efded25a41d8b33d through device /dev/xvdbb
I0924 11:30:50.081335       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-03c016c49f4f2e32b NodeId:i-0efded25a41d8b33d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
... skipping 118 lines ...
  Device: "/dev/xvdba",
  InstanceId: "i-0efded25a41d8b33d",
  State: "attaching",
  VolumeId: "vol-03b13ac3b2a490c7c"
}
I0924 11:31:39.253787       1 cloud.go:665] Waiting for volume "vol-03b13ac3b2a490c7c" state: actual=detached, desired=attached
E0924 11:31:40.067893       1 manager.go:44] Error releasing device: release on device "/dev/xvdba" assigned to different volume: "vol-0dd8b70fb7f696ccb" vs "vol-03b13ac3b2a490c7c"
I0924 11:31:40.067911       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0dd8b70fb7f696ccb detached from node i-0efded25a41d8b33d
I0924 11:31:40.320978       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-03b13ac3b2a490c7c
I0924 11:31:40.320995       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-03b13ac3b2a490c7c attached to node i-0efded25a41d8b33d through device /dev/xvdba
I0924 11:31:47.416104       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0dd8b70fb7f696ccb Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:31:47.600298       1 inflight.go:74] Node Service: volume="vol-0dd8b70fb7f696ccb" operation finished
I0924 11:31:48.455539       1 controller.go:103] CreateVolume: called with args {Name:pvc-4782489a-27f4-4ece-ba2c-737a1ce36895 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-4782489a-27f4-4ece-ba2c-737a1ce36895 csi.storage.k8s.io/pvc/name:aws7ssmt csi.storage.k8s.io/pvc/namespace:volumemode-7728] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2b" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2c" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
... skipping 4428 lines ...

Deleted cluster: "test-cluster-18977.k8s.local"
###
## OVERALL_TEST_PASSED: 1
#
###
## FAIL!
#
make: *** [Makefile:178: test-e2e-migration] Error 1
+ EXIT_VALUE=2
+ set +o xtrace
Cleaning up after docker in docker.
================================================================================
Cleaning up after docker
Stopping Docker: dockerProgram process in pidfile '/var/run/docker-ssd.pid', 1 process(es), refused to die.
... skipping 3 lines ...