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

Test Failures


AWS EBS CSI Driver End-to-End Tests [ebs-csi-e2e] [single-az] Snapshot should create a pod, write and read to it, take a volume snapshot, and create another pod from the snapshot 12m2s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=AWS\sEBS\sCSI\sDriver\sEnd\-to\-End\sTests\s\[ebs\-csi\-e2e\]\s\[single\-az\]\sSnapshot\sshould\screate\sa\spod\,\swrite\sand\sread\sto\sit\,\stake\sa\svolume\ssnapshot\,\sand\screate\sanother\spod\sfrom\sthe\ssnapshot$'
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e/dynamic_provisioning.go:454
Unexpected error:
    <*errors.errorString | 0xc0002449b0>: {
        s: "PersistentVolume pvc-8263673c-539e-4e49-8d38-fe1d34199960 still exists within 10m0s",
    }
    PersistentVolume pvc-8263673c-539e-4e49-8d38-fe1d34199960 still exists within 10m0s
occurred
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e/testsuites/testsuites.go:445
				
				Click to see stdout/stderrfrom junit_02.xml

Filter through log files | View test history on testgrid


Show 26 Passed Tests

Show 6 Skipped Tests

Error lines from build-log.txt

... skipping 216 lines ...
|+ + . . S   =    |
|.o .   . . . o . |
|. o.  ..    . o  |
| o=.. .=.. . +   |
| .+=..+o+...+    |
+----[SHA256]-----+
Error: cluster not found "test-cluster-25255.k8s.local"
###
## Creating cluster test-cluster-25255.k8s.local with /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-25255.k8s.local.kops.yaml (dry run)
#
I0924 11:10:00.731632    5896 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:10:01.453925    5896 new_cluster.go:248] Inferred "aws" cloud provider from zone "us-west-2a"
I0924 11:10:01.454047    5896 new_cluster.go:1102]  Cloud Provider ID = aws
... skipping 72 lines ...
## Validating cluster test-cluster-25255.k8s.local
#
Using cluster from kubectl context: test-cluster-25255.k8s.local

Validating cluster test-cluster-25255.k8s.local

W0924 11:10:50.654155    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:00.718050    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:10.766628    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:20.809842    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host
W0924 11:11:42.586686    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:12:04.332071    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:12:26.013994    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:12:47.753024    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.us-west-2.elb.amazonaws.com/api/v1/nodes": EOF
W0924 11:13:09.476304    6020 validate_cluster.go:184] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-25255-k8-apst3i-1679597663.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	3	3	us-west-2a

NODE STATUS
... skipping 4 lines ...
KIND	NAME						MESSAGE
Machine	i-025e3d9a8ba833c7c				machine "i-025e3d9a8ba833c7c" has not yet joined cluster
Machine	i-044f03effb64df20d				machine "i-044f03effb64df20d" has not yet joined cluster
Machine	i-0857bd1ec17e8d608				machine "i-0857bd1ec17e8d608" has not yet joined cluster
Node	ip-172-20-36-236.us-west-2.compute.internal	node "ip-172-20-36-236.us-west-2.compute.internal" of role "master" is not ready

Validation Failed
W0924 11:13:30.556605    6020 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	3	3	us-west-2a

... skipping 5 lines ...
KIND	NAME						MESSAGE
Machine	i-025e3d9a8ba833c7c				machine "i-025e3d9a8ba833c7c" has not yet joined cluster
Machine	i-044f03effb64df20d				machine "i-044f03effb64df20d" has not yet joined cluster
Machine	i-0857bd1ec17e8d608				machine "i-0857bd1ec17e8d608" has not yet joined cluster
Node	ip-172-20-36-236.us-west-2.compute.internal	node "ip-172-20-36-236.us-west-2.compute.internal" of role "master" is not ready

Validation Failed
W0924 11:13:41.988593    6020 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	3	3	us-west-2a

... skipping 6 lines ...
Machine	i-025e3d9a8ba833c7c								machine "i-025e3d9a8ba833c7c" has not yet joined cluster
Machine	i-044f03effb64df20d								machine "i-044f03effb64df20d" has not yet joined cluster
Machine	i-0857bd1ec17e8d608								machine "i-0857bd1ec17e8d608" has not yet joined cluster
Node	ip-172-20-36-236.us-west-2.compute.internal					node "ip-172-20-36-236.us-west-2.compute.internal" of role "master" is not ready
Pod	kube-system/kube-controller-manager-ip-172-20-36-236.us-west-2.compute.internal	system-cluster-critical pod "kube-controller-manager-ip-172-20-36-236.us-west-2.compute.internal" is pending

Validation Failed
W0924 11:13:53.513669    6020 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	3	3	us-west-2a

... skipping 6 lines ...
Machine	i-025e3d9a8ba833c7c							machine "i-025e3d9a8ba833c7c" has not yet joined cluster
Machine	i-044f03effb64df20d							machine "i-044f03effb64df20d" has not yet joined cluster
Machine	i-0857bd1ec17e8d608							machine "i-0857bd1ec17e8d608" has not yet joined cluster
Node	ip-172-20-36-236.us-west-2.compute.internal				node "ip-172-20-36-236.us-west-2.compute.internal" of role "master" is not ready
Pod	kube-system/kube-proxy-ip-172-20-36-236.us-west-2.compute.internal	system-node-critical pod "kube-proxy-ip-172-20-36-236.us-west-2.compute.internal" is pending

Validation Failed
W0924 11:14:04.816948    6020 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	3	3	us-west-2a

... skipping 7 lines ...
Machine	i-044f03effb64df20d				machine "i-044f03effb64df20d" has not yet joined cluster
Machine	i-0857bd1ec17e8d608				machine "i-0857bd1ec17e8d608" has not yet joined cluster
Node	ip-172-20-36-236.us-west-2.compute.internal	master "ip-172-20-36-236.us-west-2.compute.internal" is missing kube-apiserver pod
Pod	kube-system/coredns-6d467c5d59-ljn7s		system-cluster-critical pod "coredns-6d467c5d59-ljn7s" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-vcpbb	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-vcpbb" is pending

Validation Failed
W0924 11:14:16.282587    6020 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	3	3	us-west-2a

... skipping 8 lines ...
Machine	i-0857bd1ec17e8d608								machine "i-0857bd1ec17e8d608" has not yet joined cluster
Node	ip-172-20-36-236.us-west-2.compute.internal					master "ip-172-20-36-236.us-west-2.compute.internal" is missing kube-apiserver pod
Pod	kube-system/coredns-6d467c5d59-ljn7s						system-cluster-critical pod "coredns-6d467c5d59-ljn7s" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-vcpbb					system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-vcpbb" is pending
Pod	kube-system/etcd-manager-events-ip-172-20-36-236.us-west-2.compute.internal	system-cluster-critical pod "etcd-manager-events-ip-172-20-36-236.us-west-2.compute.internal" is pending

Validation Failed
W0924 11:14:27.684748    6020 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	3	3	us-west-2a

... skipping 6 lines ...
Machine	i-025e3d9a8ba833c7c				machine "i-025e3d9a8ba833c7c" has not yet joined cluster
Machine	i-044f03effb64df20d				machine "i-044f03effb64df20d" has not yet joined cluster
Machine	i-0857bd1ec17e8d608				machine "i-0857bd1ec17e8d608" has not yet joined cluster
Pod	kube-system/coredns-6d467c5d59-ljn7s		system-cluster-critical pod "coredns-6d467c5d59-ljn7s" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-vcpbb	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-vcpbb" is pending

Validation Failed
W0924 11:14:39.116386    6020 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	3	3	us-west-2a

... skipping 8 lines ...
KIND	NAME						MESSAGE
Node	ip-172-20-40-151.us-west-2.compute.internal	node "ip-172-20-40-151.us-west-2.compute.internal" of role "node" is not ready
Node	ip-172-20-53-17.us-west-2.compute.internal	node "ip-172-20-53-17.us-west-2.compute.internal" of role "node" is not ready
Pod	kube-system/coredns-6d467c5d59-ljn7s		system-cluster-critical pod "coredns-6d467c5d59-ljn7s" is pending
Pod	kube-system/coredns-autoscaler-5c7694cfcc-vcpbb	system-cluster-critical pod "coredns-autoscaler-5c7694cfcc-vcpbb" is pending

Validation Failed
W0924 11:14:50.742503    6020 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	3	3	us-west-2a

... skipping 5 lines ...
ip-172-20-53-17.us-west-2.compute.internal	node	True

VALIDATION ERRORS
KIND	NAME					MESSAGE
Pod	kube-system/coredns-6d467c5d59-hgt8f	system-cluster-critical pod "coredns-6d467c5d59-hgt8f" is not ready (coredns)

Validation Failed
W0924 11:15:02.236918    6020 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	3	3	us-west-2a

... skipping 164 lines ...
Sep 24 11:17:07.596: INFO: PersistentVolumeClaim pvc-2jkdj found but phase is Pending instead of Bound.
Sep 24 11:17:09.662: INFO: PersistentVolumeClaim pvc-2jkdj found and phase=Bound (8.340481855s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with an error
Sep 24 11:17:09.869: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-dlqqd" in namespace "ebs-1746" to be "Error status code"
Sep 24 11:17:09.934: INFO: Pod "ebs-volume-tester-dlqqd": Phase="Pending", Reason="", readiness=false. Elapsed: 65.067769ms
Sep 24 11:17:12.001: INFO: Pod "ebs-volume-tester-dlqqd": Phase="Pending", Reason="", readiness=false. Elapsed: 2.13234495s
Sep 24 11:17:14.068: INFO: Pod "ebs-volume-tester-dlqqd": Phase="Pending", Reason="", readiness=false. Elapsed: 4.198748519s
Sep 24 11:17:16.135: INFO: Pod "ebs-volume-tester-dlqqd": Phase="Pending", Reason="", readiness=false. Elapsed: 6.266288448s
Sep 24 11:17:18.203: INFO: Pod "ebs-volume-tester-dlqqd": Phase="Pending", Reason="", readiness=false. Elapsed: 8.33389487s
Sep 24 11:17:20.271: INFO: Pod "ebs-volume-tester-dlqqd": Phase="Failed", Reason="", readiness=false. Elapsed: 10.402120012s
STEP: Saw pod failure
Sep 24 11:17:20.271: INFO: Pod "ebs-volume-tester-dlqqd" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Sep 24 11:17:20.685: INFO: deleting Pod "ebs-1746"/"ebs-volume-tester-dlqqd"
Sep 24 11:17:20.752: INFO: Pod ebs-volume-tester-dlqqd has the following logs: touch: /mnt/test-1/data: Read-only file system

STEP: Deleting pod ebs-volume-tester-dlqqd in namespace ebs-1746
Sep 24 11:17:20.827: INFO: deleting PVC "ebs-1746"/"pvc-2jkdj"
... skipping 46 lines ...
Sep 24 11:17:07.554: INFO: PersistentVolumeClaim pvc-sk7kc found but phase is Pending instead of Bound.
Sep 24 11:17:09.621: INFO: PersistentVolumeClaim pvc-sk7kc found and phase=Bound (8.328444704s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:17:09.830: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-bn6s5" in namespace "ebs-8274" to be "Succeeded or Failed"
Sep 24 11:17:09.907: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Pending", Reason="", readiness=false. Elapsed: 77.528259ms
Sep 24 11:17:11.974: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Pending", Reason="", readiness=false. Elapsed: 2.144128009s
Sep 24 11:17:14.041: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Pending", Reason="", readiness=false. Elapsed: 4.210734398s
Sep 24 11:17:16.107: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Pending", Reason="", readiness=false. Elapsed: 6.277092986s
Sep 24 11:17:18.173: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Pending", Reason="", readiness=false. Elapsed: 8.343505749s
Sep 24 11:17:20.240: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Pending", Reason="", readiness=false. Elapsed: 10.409857389s
Sep 24 11:17:22.305: INFO: Pod "ebs-volume-tester-bn6s5": Phase="Succeeded", Reason="", readiness=false. Elapsed: 12.475102539s
STEP: Saw pod success
Sep 24 11:17:22.305: INFO: Pod "ebs-volume-tester-bn6s5" satisfied condition "Succeeded or Failed"
Sep 24 11:17:22.305: INFO: deleting Pod "ebs-8274"/"ebs-volume-tester-bn6s5"
Sep 24 11:17:22.371: INFO: Pod ebs-volume-tester-bn6s5 has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-bn6s5 in namespace ebs-8274
Sep 24 11:17:22.443: INFO: deleting PVC "ebs-8274"/"pvc-sk7kc"
Sep 24 11:17:22.443: INFO: Deleting PersistentVolumeClaim "pvc-sk7kc"
... skipping 108 lines ...
Sep 24 11:17:12.071: INFO: PersistentVolumeClaim pvc-ctnmn found but phase is Pending instead of Bound.
Sep 24 11:17:14.140: INFO: PersistentVolumeClaim pvc-ctnmn found and phase=Bound (4.206351819s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:17:14.355: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-nln6m" in namespace "ebs-8804" to be "Succeeded or Failed"
Sep 24 11:17:14.423: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 68.102722ms
Sep 24 11:17:16.492: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.137373947s
Sep 24 11:17:18.560: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.205639932s
Sep 24 11:17:20.629: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.274427688s
Sep 24 11:17:22.700: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.345725716s
Sep 24 11:17:24.769: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 10.414731359s
Sep 24 11:17:26.841: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 12.486068927s
Sep 24 11:17:28.910: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 14.555790474s
Sep 24 11:17:30.980: INFO: Pod "ebs-volume-tester-nln6m": Phase="Pending", Reason="", readiness=false. Elapsed: 16.625661483s
Sep 24 11:17:33.049: INFO: Pod "ebs-volume-tester-nln6m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.694577565s
STEP: Saw pod success
Sep 24 11:17:33.049: INFO: Pod "ebs-volume-tester-nln6m" satisfied condition "Succeeded or Failed"
Sep 24 11:17:33.049: INFO: deleting Pod "ebs-8804"/"ebs-volume-tester-nln6m"
Sep 24 11:17:33.119: INFO: Pod ebs-volume-tester-nln6m has the following logs: 100+0 records in
100+0 records out
104857600 bytes (100.0MB) copied, 0.052140 seconds, 1.9GB/s
hello world

... skipping 57 lines ...
Sep 24 11:17:07.520: INFO: PersistentVolumeClaim pvc-zr67v found but phase is Pending instead of Bound.
Sep 24 11:17:09.585: INFO: PersistentVolumeClaim pvc-zr67v found and phase=Bound (8.320303385s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:17:09.776: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-brkpw" in namespace "ebs-4070" to be "Succeeded or Failed"
Sep 24 11:17:09.845: INFO: Pod "ebs-volume-tester-brkpw": Phase="Pending", Reason="", readiness=false. Elapsed: 69.03877ms
Sep 24 11:17:11.913: INFO: Pod "ebs-volume-tester-brkpw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.137037948s
Sep 24 11:17:13.978: INFO: Pod "ebs-volume-tester-brkpw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.202223061s
Sep 24 11:17:16.043: INFO: Pod "ebs-volume-tester-brkpw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.26697301s
Sep 24 11:17:18.111: INFO: Pod "ebs-volume-tester-brkpw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.335116759s
Sep 24 11:17:20.176: INFO: Pod "ebs-volume-tester-brkpw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.39927159s
STEP: Saw pod success
Sep 24 11:17:20.176: INFO: Pod "ebs-volume-tester-brkpw" satisfied condition "Succeeded or Failed"
Sep 24 11:17:20.176: INFO: deleting Pod "ebs-4070"/"ebs-volume-tester-brkpw"
Sep 24 11:17:20.493: INFO: Pod ebs-volume-tester-brkpw has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-brkpw in namespace ebs-4070
Sep 24 11:17:20.566: INFO: deleting PVC "ebs-4070"/"pvc-zr67v"
Sep 24 11:17:20.566: INFO: Deleting PersistentVolumeClaim "pvc-zr67v"
... skipping 46 lines ...
Sep 24 11:17:40.694: INFO: PersistentVolumeClaim pvc-s8vht found but phase is Pending instead of Bound.
Sep 24 11:17:42.760: INFO: PersistentVolumeClaim pvc-s8vht found and phase=Bound (4.196466105s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:17:42.966: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-b2fxw" in namespace "ebs-3754" to be "Succeeded or Failed"
Sep 24 11:17:43.031: INFO: Pod "ebs-volume-tester-b2fxw": Phase="Pending", Reason="", readiness=false. Elapsed: 64.700021ms
Sep 24 11:17:45.102: INFO: Pod "ebs-volume-tester-b2fxw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135300129s
Sep 24 11:17:47.168: INFO: Pod "ebs-volume-tester-b2fxw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.201599645s
Sep 24 11:17:49.235: INFO: Pod "ebs-volume-tester-b2fxw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.268544608s
STEP: Saw pod success
Sep 24 11:17:49.235: INFO: Pod "ebs-volume-tester-b2fxw" satisfied condition "Succeeded or Failed"
Sep 24 11:17:49.235: INFO: deleting Pod "ebs-3754"/"ebs-volume-tester-b2fxw"
Sep 24 11:17:49.303: INFO: Pod ebs-volume-tester-b2fxw has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-b2fxw in namespace ebs-3754
Sep 24 11:17:49.391: INFO: deleting PVC "ebs-3754"/"pvc-s8vht"
Sep 24 11:17:49.391: INFO: Deleting PersistentVolumeClaim "pvc-s8vht"
... skipping 42 lines ...
Sep 24 11:17:49.211: INFO: PersistentVolumeClaim pvc-hrj4c found but phase is Pending instead of Bound.
Sep 24 11:17:51.278: INFO: PersistentVolumeClaim pvc-hrj4c found and phase=Bound (4.200277319s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:17:51.483: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-jrqkc" in namespace "ebs-2558" to be "Succeeded or Failed"
Sep 24 11:17:51.549: INFO: Pod "ebs-volume-tester-jrqkc": Phase="Pending", Reason="", readiness=false. Elapsed: 65.889077ms
Sep 24 11:17:53.616: INFO: Pod "ebs-volume-tester-jrqkc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.133721566s
Sep 24 11:17:55.682: INFO: Pod "ebs-volume-tester-jrqkc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.199656282s
Sep 24 11:17:57.750: INFO: Pod "ebs-volume-tester-jrqkc": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.26703298s
STEP: Saw pod success
Sep 24 11:17:57.750: INFO: Pod "ebs-volume-tester-jrqkc" satisfied condition "Succeeded or Failed"
Sep 24 11:17:57.750: INFO: deleting Pod "ebs-2558"/"ebs-volume-tester-jrqkc"
Sep 24 11:17:57.816: INFO: Pod ebs-volume-tester-jrqkc has the following logs: 100+0 records in
100+0 records out
104857600 bytes (100.0MB) copied, 0.050461 seconds, 1.9GB/s

STEP: Deleting pod ebs-volume-tester-jrqkc in namespace ebs-2558
... skipping 147 lines ...
Sep 24 11:17:58.797: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-k78bj] to have phase Bound
Sep 24 11:17:58.866: INFO: PersistentVolumeClaim pvc-k78bj found and phase=Bound (68.150847ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with an error
Sep 24 11:17:59.074: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-6gxp6" in namespace "ebs-449" to be "Error status code"
Sep 24 11:17:59.143: INFO: Pod "ebs-volume-tester-6gxp6": Phase="Pending", Reason="", readiness=false. Elapsed: 68.148823ms
Sep 24 11:18:01.211: INFO: Pod "ebs-volume-tester-6gxp6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.137017184s
Sep 24 11:18:03.281: INFO: Pod "ebs-volume-tester-6gxp6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206117427s
Sep 24 11:18:05.351: INFO: Pod "ebs-volume-tester-6gxp6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.276384668s
Sep 24 11:18:07.421: INFO: Pod "ebs-volume-tester-6gxp6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.346832286s
Sep 24 11:18:09.491: INFO: Pod "ebs-volume-tester-6gxp6": Phase="Failed", Reason="", readiness=false. Elapsed: 10.416611327s
STEP: Saw pod failure
Sep 24 11:18:09.491: INFO: Pod "ebs-volume-tester-6gxp6" satisfied condition "Error status code"
STEP: checking that pod logs contain expected message
Sep 24 11:18:09.561: INFO: deleting Pod "ebs-449"/"ebs-volume-tester-6gxp6"
Sep 24 11:18:09.632: INFO: Pod ebs-volume-tester-6gxp6 has the following logs: /bin/sh: can't create /mnt/test-1/data: Read-only file system

STEP: Deleting pod ebs-volume-tester-6gxp6 in namespace ebs-449
Sep 24 11:18:09.708: INFO: deleting PVC "ebs-449"/"pvc-k78bj"
... skipping 49 lines ...
Sep 24 11:18:24.954: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-fk8q9] to have phase Bound
Sep 24 11:18:25.020: INFO: PersistentVolumeClaim pvc-fk8q9 found and phase=Bound (65.557037ms)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:18:25.226: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-57stm" in namespace "ebs-3607" to be "Succeeded or Failed"
Sep 24 11:18:25.292: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 65.70457ms
Sep 24 11:18:27.359: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.132094454s
Sep 24 11:18:29.425: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.198839257s
Sep 24 11:18:31.490: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 6.264067467s
Sep 24 11:18:33.557: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 8.330629162s
Sep 24 11:18:35.623: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 10.39619844s
Sep 24 11:18:37.689: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 12.462895879s
Sep 24 11:18:39.756: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 14.529080457s
Sep 24 11:18:41.823: INFO: Pod "ebs-volume-tester-57stm": Phase="Pending", Reason="", readiness=false. Elapsed: 16.596110692s
Sep 24 11:18:43.887: INFO: Pod "ebs-volume-tester-57stm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.661048009s
STEP: Saw pod success
Sep 24 11:18:43.888: INFO: Pod "ebs-volume-tester-57stm" satisfied condition "Succeeded or Failed"
Sep 24 11:18:43.888: INFO: deleting Pod "ebs-3607"/"ebs-volume-tester-57stm"
Sep 24 11:18:43.954: INFO: Pod ebs-volume-tester-57stm has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-57stm in namespace ebs-3607
Sep 24 11:18:44.026: INFO: deleting PVC "ebs-3607"/"pvc-fk8q9"
Sep 24 11:18:44.026: INFO: Deleting PersistentVolumeClaim "pvc-fk8q9"
... skipping 51 lines ...
STEP: checking the resizing PV result
STEP: Waiting up to 1m0s for pv in namespace "ebs-3683" to be complete
STEP: Pv size is updated to 2Gi
STEP: Validate volume can be attached
STEP: deploying the pod
STEP: checking that the pods is running
Sep 24 11:18:35.929: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-f95tx" in namespace "ebs-3683" to be "Succeeded or Failed"
Sep 24 11:18:36.000: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 71.047263ms
Sep 24 11:18:38.071: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.142421942s
Sep 24 11:18:40.142: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.212547537s
Sep 24 11:18:42.211: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.281995842s
Sep 24 11:18:44.280: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.351079937s
Sep 24 11:18:46.349: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.420027341s
Sep 24 11:18:48.422: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 12.493488296s
Sep 24 11:18:50.492: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 14.563405182s
Sep 24 11:18:52.563: INFO: Pod "ebs-volume-tester-f95tx": Phase="Pending", Reason="", readiness=false. Elapsed: 16.634194044s
Sep 24 11:18:54.633: INFO: Pod "ebs-volume-tester-f95tx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 18.70383895s
STEP: Saw pod success
Sep 24 11:18:54.633: INFO: Pod "ebs-volume-tester-f95tx" satisfied condition "Succeeded or Failed"
Sep 24 11:18:54.633: INFO: deleting Pod "ebs-3683"/"ebs-volume-tester-f95tx"
Sep 24 11:18:54.718: INFO: Pod ebs-volume-tester-f95tx has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-f95tx in namespace ebs-3683
Sep 24 11:18:54.793: INFO: deleting PVC "ebs-3683"/"pvc-x4n4m"
Sep 24 11:18:54.793: INFO: Deleting PersistentVolumeClaim "pvc-x4n4m"
... skipping 40 lines ...
Sep 24 11:18:57.519: INFO: PersistentVolumeClaim pvc-c7fww found but phase is Pending instead of Bound.
Sep 24 11:18:59.591: INFO: PersistentVolumeClaim pvc-c7fww found and phase=Bound (4.203842932s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:18:59.787: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-z94f9" in namespace "ebs-7318" to be "Succeeded or Failed"
Sep 24 11:18:59.852: INFO: Pod "ebs-volume-tester-z94f9": Phase="Pending", Reason="", readiness=false. Elapsed: 65.409198ms
Sep 24 11:19:01.919: INFO: Pod "ebs-volume-tester-z94f9": Phase="Pending", Reason="", readiness=false. Elapsed: 2.132510174s
Sep 24 11:19:04.009: INFO: Pod "ebs-volume-tester-z94f9": Phase="Pending", Reason="", readiness=false. Elapsed: 4.222439666s
Sep 24 11:19:06.078: INFO: Pod "ebs-volume-tester-z94f9": Phase="Pending", Reason="", readiness=false. Elapsed: 6.291463027s
Sep 24 11:19:08.150: INFO: Pod "ebs-volume-tester-z94f9": Phase="Pending", Reason="", readiness=false. Elapsed: 8.363004492s
Sep 24 11:19:10.216: INFO: Pod "ebs-volume-tester-z94f9": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.42899603s
STEP: Saw pod success
Sep 24 11:19:10.216: INFO: Pod "ebs-volume-tester-z94f9" satisfied condition "Succeeded or Failed"
Sep 24 11:19:10.216: INFO: deleting Pod "ebs-7318"/"ebs-volume-tester-z94f9"
Sep 24 11:19:10.287: INFO: Pod ebs-volume-tester-z94f9 has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-z94f9 in namespace ebs-7318
Sep 24 11:19:10.367: INFO: deleting PVC "ebs-7318"/"pvc-c7fww"
Sep 24 11:19:10.367: INFO: Deleting PersistentVolumeClaim "pvc-c7fww"
... skipping 164 lines ...
Sep 24 11:19:07.931: INFO: PersistentVolumeClaim pvc-pjsv4 found but phase is Pending instead of Bound.
Sep 24 11:19:10.000: INFO: PersistentVolumeClaim pvc-pjsv4 found and phase=Bound (4.206702863s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:19:10.210: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-8l77h" in namespace "ebs-6460" to be "Succeeded or Failed"
Sep 24 11:19:10.279: INFO: Pod "ebs-volume-tester-8l77h": Phase="Pending", Reason="", readiness=false. Elapsed: 69.072789ms
Sep 24 11:19:12.348: INFO: Pod "ebs-volume-tester-8l77h": Phase="Pending", Reason="", readiness=false. Elapsed: 2.138427501s
Sep 24 11:19:14.418: INFO: Pod "ebs-volume-tester-8l77h": Phase="Pending", Reason="", readiness=false. Elapsed: 4.208618222s
Sep 24 11:19:16.488: INFO: Pod "ebs-volume-tester-8l77h": Phase="Pending", Reason="", readiness=false. Elapsed: 6.27816591s
Sep 24 11:19:18.558: INFO: Pod "ebs-volume-tester-8l77h": Phase="Pending", Reason="", readiness=false. Elapsed: 8.347778334s
Sep 24 11:19:20.631: INFO: Pod "ebs-volume-tester-8l77h": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.421364573s
STEP: Saw pod success
Sep 24 11:19:20.631: INFO: Pod "ebs-volume-tester-8l77h" satisfied condition "Succeeded or Failed"
Sep 24 11:19:20.631: INFO: deleting Pod "ebs-6460"/"ebs-volume-tester-8l77h"
Sep 24 11:19:20.702: INFO: Pod ebs-volume-tester-8l77h has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-8l77h in namespace ebs-6460
Sep 24 11:19:20.775: INFO: deleting PVC "ebs-6460"/"pvc-pjsv4"
Sep 24 11:19:20.775: INFO: Deleting PersistentVolumeClaim "pvc-pjsv4"
... skipping 46 lines ...
Sep 24 11:19:28.562: INFO: PersistentVolumeClaim pvc-lmdx7 found but phase is Pending instead of Bound.
Sep 24 11:19:30.629: INFO: PersistentVolumeClaim pvc-lmdx7 found and phase=Bound (4.197086162s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:19:30.829: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-frl7m" in namespace "ebs-611" to be "Succeeded or Failed"
Sep 24 11:19:30.898: INFO: Pod "ebs-volume-tester-frl7m": Phase="Pending", Reason="", readiness=false. Elapsed: 69.625975ms
Sep 24 11:19:32.966: INFO: Pod "ebs-volume-tester-frl7m": Phase="Pending", Reason="", readiness=false. Elapsed: 2.136990152s
Sep 24 11:19:35.032: INFO: Pod "ebs-volume-tester-frl7m": Phase="Pending", Reason="", readiness=false. Elapsed: 4.202962051s
Sep 24 11:19:37.101: INFO: Pod "ebs-volume-tester-frl7m": Phase="Pending", Reason="", readiness=false. Elapsed: 6.272095307s
Sep 24 11:19:39.167: INFO: Pod "ebs-volume-tester-frl7m": Phase="Pending", Reason="", readiness=false. Elapsed: 8.338082089s
Sep 24 11:19:41.233: INFO: Pod "ebs-volume-tester-frl7m": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.404203012s
STEP: Saw pod success
Sep 24 11:19:41.233: INFO: Pod "ebs-volume-tester-frl7m" satisfied condition "Succeeded or Failed"
Sep 24 11:19:41.233: INFO: deleting Pod "ebs-611"/"ebs-volume-tester-frl7m"
Sep 24 11:19:41.300: INFO: Pod ebs-volume-tester-frl7m has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-frl7m in namespace ebs-611
Sep 24 11:19:41.379: INFO: deleting PVC "ebs-611"/"pvc-lmdx7"
Sep 24 11:19:41.379: INFO: Deleting PersistentVolumeClaim "pvc-lmdx7"
... skipping 44 lines ...
Sep 24 11:19:40.372: INFO: PersistentVolumeClaim pvc-tr79k found but phase is Pending instead of Bound.
Sep 24 11:19:42.436: INFO: PersistentVolumeClaim pvc-tr79k found and phase=Bound (4.192914359s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:19:42.627: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-s4mg7" in namespace "ebs-4442" to be "Succeeded or Failed"
Sep 24 11:19:42.691: INFO: Pod "ebs-volume-tester-s4mg7": Phase="Pending", Reason="", readiness=false. Elapsed: 63.822584ms
Sep 24 11:19:44.756: INFO: Pod "ebs-volume-tester-s4mg7": Phase="Pending", Reason="", readiness=false. Elapsed: 2.128310602s
Sep 24 11:19:46.821: INFO: Pod "ebs-volume-tester-s4mg7": Phase="Pending", Reason="", readiness=false. Elapsed: 4.193466369s
Sep 24 11:19:48.886: INFO: Pod "ebs-volume-tester-s4mg7": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.25868118s
STEP: Saw pod success
Sep 24 11:19:48.886: INFO: Pod "ebs-volume-tester-s4mg7" satisfied condition "Succeeded or Failed"
Sep 24 11:19:48.886: INFO: deleting Pod "ebs-4442"/"ebs-volume-tester-s4mg7"
Sep 24 11:19:48.951: INFO: Pod ebs-volume-tester-s4mg7 has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-s4mg7 in namespace ebs-4442
Sep 24 11:19:49.022: INFO: deleting PVC "ebs-4442"/"pvc-tr79k"
Sep 24 11:19:49.022: INFO: Deleting PersistentVolumeClaim "pvc-tr79k"
... skipping 44 lines ...
Sep 24 11:20:11.325: INFO: PersistentVolumeClaim pvc-8m476 found but phase is Pending instead of Bound.
Sep 24 11:20:13.391: INFO: PersistentVolumeClaim pvc-8m476 found and phase=Bound (8.323685424s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:20:13.585: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-k9ptw" in namespace "ebs-7792" to be "Succeeded or Failed"
Sep 24 11:20:13.648: INFO: Pod "ebs-volume-tester-k9ptw": Phase="Pending", Reason="", readiness=false. Elapsed: 63.026979ms
Sep 24 11:20:15.713: INFO: Pod "ebs-volume-tester-k9ptw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.128684162s
Sep 24 11:20:17.778: INFO: Pod "ebs-volume-tester-k9ptw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.193020673s
Sep 24 11:20:19.842: INFO: Pod "ebs-volume-tester-k9ptw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.257375003s
STEP: Saw pod success
Sep 24 11:20:19.842: INFO: Pod "ebs-volume-tester-k9ptw" satisfied condition "Succeeded or Failed"
Sep 24 11:20:19.842: INFO: deleting Pod "ebs-7792"/"ebs-volume-tester-k9ptw"
Sep 24 11:20:19.907: INFO: Pod ebs-volume-tester-k9ptw has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-k9ptw in namespace ebs-7792
Sep 24 11:20:19.982: INFO: deleting PVC "ebs-7792"/"pvc-8m476"
Sep 24 11:20:19.982: INFO: Deleting PersistentVolumeClaim "pvc-8m476"
... skipping 54 lines ...
Sep 24 11:20:04.161: INFO: PersistentVolumeClaim pvc-rck9g found but phase is Pending instead of Bound.
Sep 24 11:20:06.227: INFO: PersistentVolumeClaim pvc-rck9g found and phase=Bound (4.202262459s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:20:06.423: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-9fn6k" in namespace "ebs-2108" to be "Succeeded or Failed"
Sep 24 11:20:06.488: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 64.92315ms
Sep 24 11:20:08.555: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.132327631s
Sep 24 11:20:10.624: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.200779591s
Sep 24 11:20:12.690: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.267663447s
Sep 24 11:20:14.756: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.332977726s
Sep 24 11:20:16.823: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.400141404s
Sep 24 11:20:18.890: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 12.46690621s
Sep 24 11:20:20.956: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 14.5333552s
Sep 24 11:20:23.024: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Pending", Reason="", readiness=false. Elapsed: 16.601685693s
Sep 24 11:20:25.091: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Running", Reason="", readiness=true. Elapsed: 18.667816255s
Sep 24 11:20:27.156: INFO: Pod "ebs-volume-tester-9fn6k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.733612397s
STEP: Saw pod success
Sep 24 11:20:27.156: INFO: Pod "ebs-volume-tester-9fn6k" satisfied condition "Succeeded or Failed"
Sep 24 11:20:27.156: INFO: deleting Pod "ebs-2108"/"ebs-volume-tester-9fn6k"
Sep 24 11:20:27.224: INFO: Pod ebs-volume-tester-9fn6k has the following logs: hello world
hello world

STEP: Deleting pod ebs-volume-tester-9fn6k in namespace ebs-2108
Sep 24 11:20:27.297: INFO: deleting PVC "ebs-2108"/"pvc-rck9g"
... skipping 52 lines ...
Sep 24 11:20:50.846: INFO: PersistentVolumeClaim pvc-pg5ng found but phase is Pending instead of Bound.
Sep 24 11:20:52.914: INFO: PersistentVolumeClaim pvc-pg5ng found and phase=Bound (4.202804368s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:20:53.114: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-r5hpm" in namespace "ebs-6426" to be "Succeeded or Failed"
Sep 24 11:20:53.180: INFO: Pod "ebs-volume-tester-r5hpm": Phase="Pending", Reason="", readiness=false. Elapsed: 66.052625ms
Sep 24 11:20:55.247: INFO: Pod "ebs-volume-tester-r5hpm": Phase="Pending", Reason="", readiness=false. Elapsed: 2.132760142s
Sep 24 11:20:57.314: INFO: Pod "ebs-volume-tester-r5hpm": Phase="Pending", Reason="", readiness=false. Elapsed: 4.199764535s
Sep 24 11:20:59.381: INFO: Pod "ebs-volume-tester-r5hpm": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.267417826s
STEP: Saw pod success
Sep 24 11:20:59.381: INFO: Pod "ebs-volume-tester-r5hpm" satisfied condition "Succeeded or Failed"
Sep 24 11:20:59.381: INFO: deleting Pod "ebs-6426"/"ebs-volume-tester-r5hpm"
Sep 24 11:20:59.449: INFO: Pod ebs-volume-tester-r5hpm has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-r5hpm in namespace ebs-6426
Sep 24 11:20:59.522: INFO: deleting PVC "ebs-6426"/"pvc-pg5ng"
Sep 24 11:20:59.522: INFO: Deleting PersistentVolumeClaim "pvc-pg5ng"
... skipping 141 lines ...
Sep 24 11:21:17.758: INFO: PersistentVolumeClaim pvc-c89nd found but phase is Pending instead of Bound.
Sep 24 11:21:19.826: INFO: PersistentVolumeClaim pvc-c89nd found and phase=Bound (4.201778371s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:21:20.027: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-vlzhw" in namespace "ebs-8139" to be "Succeeded or Failed"
Sep 24 11:21:20.096: INFO: Pod "ebs-volume-tester-vlzhw": Phase="Pending", Reason="", readiness=false. Elapsed: 69.276121ms
Sep 24 11:21:22.163: INFO: Pod "ebs-volume-tester-vlzhw": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135911895s
Sep 24 11:21:24.230: INFO: Pod "ebs-volume-tester-vlzhw": Phase="Pending", Reason="", readiness=false. Elapsed: 4.203766307s
Sep 24 11:21:26.297: INFO: Pod "ebs-volume-tester-vlzhw": Phase="Pending", Reason="", readiness=false. Elapsed: 6.270241941s
Sep 24 11:21:28.363: INFO: Pod "ebs-volume-tester-vlzhw": Phase="Pending", Reason="", readiness=false. Elapsed: 8.336436406s
Sep 24 11:21:30.435: INFO: Pod "ebs-volume-tester-vlzhw": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.408480249s
STEP: Saw pod success
Sep 24 11:21:30.435: INFO: Pod "ebs-volume-tester-vlzhw" satisfied condition "Succeeded or Failed"
STEP: setting up the StorageClass
STEP: creating a StorageClass 
STEP: setting up the PVC and PV
STEP: creating a PVC
STEP: waiting for PVC to be in phase "Bound"
Sep 24 11:21:30.572: INFO: Waiting up to timeout=5m0s for PersistentVolumeClaims [pvc-9p22f] to have phase Bound
Sep 24 11:21:30.638: INFO: PersistentVolumeClaim pvc-9p22f found but phase is Pending instead of Bound.
Sep 24 11:21:32.705: INFO: PersistentVolumeClaim pvc-9p22f found but phase is Pending instead of Bound.
Sep 24 11:21:34.773: INFO: PersistentVolumeClaim pvc-9p22f found and phase=Bound (4.201544664s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:21:34.975: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-jkjhz" in namespace "ebs-8139" to be "Succeeded or Failed"
Sep 24 11:21:35.042: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 66.398581ms
Sep 24 11:21:37.110: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.134724489s
Sep 24 11:21:39.178: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.202400419s
Sep 24 11:21:41.244: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.269165585s
Sep 24 11:21:43.311: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.335927394s
Sep 24 11:21:45.379: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 10.403758297s
Sep 24 11:21:47.446: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 12.470726666s
Sep 24 11:21:49.514: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 14.539152469s
Sep 24 11:21:51.581: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 16.605778261s
Sep 24 11:21:53.648: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Pending", Reason="", readiness=false. Elapsed: 18.67271982s
Sep 24 11:21:55.715: INFO: Pod "ebs-volume-tester-jkjhz": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.740165711s
STEP: Saw pod success
Sep 24 11:21:55.715: INFO: Pod "ebs-volume-tester-jkjhz" satisfied condition "Succeeded or Failed"
Sep 24 11:21:55.715: INFO: deleting Pod "ebs-8139"/"ebs-volume-tester-jkjhz"
Sep 24 11:21:55.783: INFO: Pod ebs-volume-tester-jkjhz has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-jkjhz in namespace ebs-8139
Sep 24 11:21:55.856: INFO: deleting PVC "ebs-8139"/"pvc-9p22f"
Sep 24 11:21:55.856: INFO: Deleting PersistentVolumeClaim "pvc-9p22f"
... skipping 54 lines ...
Sep 24 11:22:00.449: INFO: PersistentVolumeClaim pvc-nvdhv found but phase is Pending instead of Bound.
Sep 24 11:22:02.519: INFO: PersistentVolumeClaim pvc-nvdhv found and phase=Bound (4.206942099s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:22:02.728: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-b4fk6" in namespace "ebs-9539" to be "Succeeded or Failed"
Sep 24 11:22:02.797: INFO: Pod "ebs-volume-tester-b4fk6": Phase="Pending", Reason="", readiness=false. Elapsed: 68.671617ms
Sep 24 11:22:04.866: INFO: Pod "ebs-volume-tester-b4fk6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.137806866s
Sep 24 11:22:06.935: INFO: Pod "ebs-volume-tester-b4fk6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.207237677s
Sep 24 11:22:09.004: INFO: Pod "ebs-volume-tester-b4fk6": Phase="Succeeded", Reason="", readiness=false. Elapsed: 6.275868372s
STEP: Saw pod success
Sep 24 11:22:09.004: INFO: Pod "ebs-volume-tester-b4fk6" satisfied condition "Succeeded or Failed"
Sep 24 11:22:09.004: INFO: deleting Pod "ebs-9539"/"ebs-volume-tester-b4fk6"
Sep 24 11:22:09.074: INFO: Pod ebs-volume-tester-b4fk6 has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-b4fk6 in namespace ebs-9539
Sep 24 11:22:09.150: INFO: deleting PVC "ebs-9539"/"pvc-nvdhv"
Sep 24 11:22:09.150: INFO: Deleting PersistentVolumeClaim "pvc-nvdhv"
... skipping 46 lines ...
Sep 24 11:22:14.482: INFO: PersistentVolumeClaim pvc-vpsgh found but phase is Pending instead of Bound.
Sep 24 11:22:16.549: INFO: PersistentVolumeClaim pvc-vpsgh found and phase=Bound (4.199913997s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:22:16.750: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-dz4cr" in namespace "ebs-4963" to be "Succeeded or Failed"
Sep 24 11:22:16.816: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 65.903224ms
Sep 24 11:22:18.886: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 2.136203142s
Sep 24 11:22:20.957: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 4.206598908s
Sep 24 11:22:23.024: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 6.273719853s
Sep 24 11:22:25.091: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 8.34113104s
Sep 24 11:22:27.159: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 10.408539372s
Sep 24 11:22:29.226: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 12.476215363s
Sep 24 11:22:31.293: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 14.542958868s
Sep 24 11:22:33.362: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 16.611917705s
Sep 24 11:22:35.430: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Pending", Reason="", readiness=false. Elapsed: 18.67954119s
Sep 24 11:22:37.498: INFO: Pod "ebs-volume-tester-dz4cr": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.747576905s
STEP: Saw pod success
Sep 24 11:22:37.498: INFO: Pod "ebs-volume-tester-dz4cr" satisfied condition "Succeeded or Failed"
Sep 24 11:22:37.498: INFO: deleting Pod "ebs-4963"/"ebs-volume-tester-dz4cr"
Sep 24 11:22:37.565: INFO: Pod ebs-volume-tester-dz4cr has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-dz4cr in namespace ebs-4963
Sep 24 11:22:37.640: INFO: deleting PVC "ebs-4963"/"pvc-vpsgh"
Sep 24 11:22:37.640: INFO: Deleting PersistentVolumeClaim "pvc-vpsgh"
... skipping 45 lines ...
STEP: setting up the StorageClass
STEP: creating a StorageClass 
STEP: setting up the PVC and PV
STEP: Create tpvc with data source
STEP: creating a PVC
STEP: deploying a second pod with a volume restored from the snapshot
STEP: checking that the pods command exits with no error
Sep 24 11:18:18.106: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-gzz2k" in namespace "ebs-7796" to be "Succeeded or Failed"
Sep 24 11:18:18.172: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 65.722596ms
Sep 24 11:18:20.239: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 2.132765933s
Sep 24 11:18:22.306: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 4.199035573s
Sep 24 11:18:24.372: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 6.26521685s
Sep 24 11:18:26.439: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 8.332516939s
Sep 24 11:18:28.506: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 10.399106548s
... skipping 389 lines ...
Sep 24 11:31:55.261: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m37.154430424s
Sep 24 11:31:57.328: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m39.221222841s
Sep 24 11:31:59.396: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m41.289122178s
Sep 24 11:32:01.464: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Pending", Reason="", readiness=false. Elapsed: 13m43.35700589s
Sep 24 11:32:03.532: INFO: Pod "ebs-volume-tester-gzz2k": Phase="Succeeded", Reason="", readiness=false. Elapsed: 13m45.425418345s
STEP: Saw pod success
Sep 24 11:32:03.532: INFO: Pod "ebs-volume-tester-gzz2k" satisfied condition "Succeeded or Failed"
Sep 24 11:32:03.532: INFO: deleting Pod "ebs-7796"/"ebs-volume-tester-gzz2k"
Sep 24 11:32:03.617: INFO: Pod ebs-volume-tester-gzz2k has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-gzz2k in namespace ebs-7796
Sep 24 11:32:03.704: INFO: deleting PVC "ebs-7796"/"pvc-lt4cm"
Sep 24 11:32:03.704: INFO: Deleting PersistentVolumeClaim "pvc-lt4cm"
... skipping 46 lines ...
Sep 24 11:20:38.152: INFO: PersistentVolumeClaim pvc-z4j25 found but phase is Pending instead of Bound.
Sep 24 11:20:40.218: INFO: PersistentVolumeClaim pvc-z4j25 found and phase=Bound (4.192917893s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying the pod
STEP: checking that the pods command exits with no error
Sep 24 11:20:40.421: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-gpshx" in namespace "ebs-2852" to be "Succeeded or Failed"
Sep 24 11:20:40.484: INFO: Pod "ebs-volume-tester-gpshx": Phase="Pending", Reason="", readiness=false. Elapsed: 63.070722ms
Sep 24 11:20:42.551: INFO: Pod "ebs-volume-tester-gpshx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.129708913s
Sep 24 11:20:44.616: INFO: Pod "ebs-volume-tester-gpshx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.195290103s
Sep 24 11:20:46.680: INFO: Pod "ebs-volume-tester-gpshx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.259267013s
Sep 24 11:20:48.746: INFO: Pod "ebs-volume-tester-gpshx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.324493324s
Sep 24 11:20:50.811: INFO: Pod "ebs-volume-tester-gpshx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 10.389374166s
STEP: Saw pod success
Sep 24 11:20:50.811: INFO: Pod "ebs-volume-tester-gpshx" satisfied condition "Succeeded or Failed"
STEP: taking snapshots
STEP: setting up the VolumeSnapshotClass
STEP: creating a VolumeSnapshotClass
STEP: creating a VolumeSnapshot for pvc-z4j25
STEP: waiting for VolumeSnapshot to be ready to use - volume-snapshot-4x2lb
STEP: setting up the StorageClass
... skipping 7 lines ...
Sep 24 11:21:53.295: INFO: PersistentVolumeClaim pvc-rjdxw found but phase is Pending instead of Bound.
Sep 24 11:21:55.361: INFO: PersistentVolumeClaim pvc-rjdxw found and phase=Bound (4.194429559s)
STEP: checking the PVC
STEP: validating provisioned PV
STEP: checking the PV
STEP: deploying a second pod with a volume restored from the snapshot
STEP: checking that the pods command exits with no error
Sep 24 11:21:55.554: INFO: Waiting up to 15m0s for pod "ebs-volume-tester-knq49" in namespace "ebs-2852" to be "Succeeded or Failed"
Sep 24 11:21:55.618: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 64.529516ms
Sep 24 11:21:57.682: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 2.128106376s
Sep 24 11:21:59.747: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 4.193071767s
Sep 24 11:22:01.814: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 6.259822873s
Sep 24 11:22:03.878: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 8.323894356s
Sep 24 11:22:05.943: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 10.388785538s
Sep 24 11:22:08.007: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 12.452836329s
Sep 24 11:22:10.071: INFO: Pod "ebs-volume-tester-knq49": Phase="Pending", Reason="", readiness=false. Elapsed: 14.517386225s
Sep 24 11:22:12.136: INFO: Pod "ebs-volume-tester-knq49": Phase="Succeeded", Reason="", readiness=false. Elapsed: 16.581889098s
STEP: Saw pod success
Sep 24 11:22:12.136: INFO: Pod "ebs-volume-tester-knq49" satisfied condition "Succeeded or Failed"
Sep 24 11:22:12.136: INFO: deleting Pod "ebs-2852"/"ebs-volume-tester-knq49"
Sep 24 11:22:12.201: INFO: Pod ebs-volume-tester-knq49 has the following logs: hello world

STEP: Deleting pod ebs-volume-tester-knq49 in namespace ebs-2852
Sep 24 11:22:12.272: INFO: deleting PVC "ebs-2852"/"pvc-rjdxw"
Sep 24 11:22:12.272: INFO: Deleting PersistentVolumeClaim "pvc-rjdxw"
... skipping 267 lines ...
• Failure [722.990 seconds]
[ebs-csi-e2e] [single-az] Snapshot
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e/dynamic_provisioning.go:433
  should create a pod, write and read to it, take a volume snapshot, and create another pod from the snapshot [It]
  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e/dynamic_provisioning.go:454

  Unexpected error:
      <*errors.errorString | 0xc0002449b0>: {
          s: "PersistentVolume pvc-8263673c-539e-4e49-8d38-fe1d34199960 still exists within 10m0s",
      }
      PersistentVolume pvc-8263673c-539e-4e49-8d38-fe1d34199960 still exists within 10m0s
  occurred

  /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e/testsuites/testsuites.go:445
------------------------------


Summarizing 1 Failure:

[Fail] [ebs-csi-e2e] [single-az] Snapshot [It] should create a pod, write and read to it, take a volume snapshot, and create another pod from the snapshot 
/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e/testsuites/testsuites.go:445

Ran 27 of 33 Specs in 938.009 seconds
FAIL! -- 26 Passed | 1 Failed | 0 Pending | 6 Skipped


Ginkgo ran 1 suite in 16m54.266122307s
Test Suite Failed
+ TEST_PASSED=1
+ set -e
+ set +x
###
## TEST_PASSED: 1
#
... skipping 350 lines ...
I0924 11:19:44.366884       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-070719cb4aef79157 attached to node i-044f03effb64df20d through device /dev/xvdbb
I0924 11:19:44.372403       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-070719cb4aef79157 NodeId:i-044f03effb64df20d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1664018127984-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:19:44.567214       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-070719cb4aef79157 attached to node i-044f03effb64df20d through device /dev/xvdbb
I0924 11:19:44.683135       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-0d20534ac8feacb9e NodeId:i-044f03effb64df20d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:19:45.043290       1 cloud.go:665] Waiting for volume "vol-0d20534ac8feacb9e" state: actual=detaching, desired=detached
I0924 11:19:46.107416       1 cloud.go:665] Waiting for volume "vol-0d20534ac8feacb9e" state: actual=detaching, desired=detached
W0924 11:19:47.725750       1 cloud.go:606] Ignoring error from describe volume for volume "vol-07a11f69eb4d91f66"; will retry: "RequestCanceled: request context canceled\ncaused by: context canceled"
I0924 11:19:47.972353       1 cloud.go:665] Waiting for volume "vol-0d20534ac8feacb9e" state: actual=detaching, desired=detached
I0924 11:19:51.278329       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0d20534ac8feacb9e detached from node i-044f03effb64df20d
I0924 11:19:51.846881       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-07a11f69eb4d91f66 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:19:51.979387       1 inflight.go:74] Node Service: volume="vol-07a11f69eb4d91f66" operation finished
I0924 11:19:54.704745       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-070719cb4aef79157 NodeId:i-044f03effb64df20d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:19:55.120567       1 cloud.go:665] Waiting for volume "vol-070719cb4aef79157" state: actual=detaching, desired=detached
... skipping 18 lines ...
  VolumeId: "vol-0815c40986b00936e"
}
I0924 11:20:02.534034       1 cloud.go:665] Waiting for volume "vol-0815c40986b00936e" state: actual=attaching, desired=attached
I0924 11:20:03.595592       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdba -> volume vol-0815c40986b00936e
I0924 11:20:03.595610       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0815c40986b00936e attached to node i-044f03effb64df20d through device /dev/xvdba
I0924 11:20:03.637749       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0815c40986b00936e NodeId:i-044f03effb64df20d VolumeCapability:mount:<fs_type:"ext3" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1664018127984-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
E0924 11:20:03.840984       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-0815c40986b00936e" to node "i-044f03effb64df20d": attachment of disk "vol-0815c40986b00936e" failed, expected device to be attached but was detached
I0924 11:20:04.086317       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-070719cb4aef79157 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:04.208618       1 inflight.go:74] Node Service: volume="vol-070719cb4aef79157" operation finished
I0924 11:20:05.047941       1 controller.go:103] CreateVolume: called with args {Name:pvc-0748fff4-613f-486f-be01-6beef0c06150 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-0748fff4-613f-486f-be01-6beef0c06150 csi.storage.k8s.io/pvc/name:pvc-8m476 csi.storage.k8s.io/pvc/namespace:ebs-7792 iops:3000 throughput:750 type:gp3] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:05.502967       1 inflight.go:74] Node Service: volume="pvc-2294f911-cb80-45db-83ee-50d7edc825d8" operation finished
I0924 11:20:06.461183       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0b49c944d57bec316 NodeId:i-044f03effb64df20d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1664018127984-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:06.466498       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0128e220fdf2f6feb NodeId:i-044f03effb64df20d VolumeCapability:mount:<fs_type:"ext3" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1664018127984-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:20:06.621699       1 cloud.go:606] Ignoring error from describe volume for volume "vol-07a11f69eb4d91f66"; will retry: "RequestCanceled: request context canceled\ncaused by: context canceled"
I0924 11:20:07.036359       1 cloud.go:492] [Debug] AttachVolume volume="vol-0128e220fdf2f6feb" instance="i-044f03effb64df20d" request returned {
  AttachTime: 2022-09-24 11:20:07.019 +0000 UTC,
  Device: "/dev/xvdbb",
  InstanceId: "i-044f03effb64df20d",
  State: "attaching",
  VolumeId: "vol-0128e220fdf2f6feb"
... skipping 53 lines ...
I0924 11:20:36.213367       1 cloud.go:665] Waiting for volume "vol-0b49c944d57bec316" state: actual=detaching, desired=detached
I0924 11:20:36.335741       1 cloud.go:665] Waiting for volume "vol-0128e220fdf2f6feb" state: actual=detaching, desired=detached
I0924 11:20:38.078304       1 cloud.go:665] Waiting for volume "vol-0b49c944d57bec316" state: actual=detaching, desired=detached
I0924 11:20:38.215748       1 cloud.go:665] Waiting for volume "vol-0128e220fdf2f6feb" state: actual=detaching, desired=detached
I0924 11:20:39.308624       1 inflight.go:74] Node Service: volume="pvc-8263673c-539e-4e49-8d38-fe1d34199960" operation finished
I0924 11:20:40.455435       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-05531c1e5105b97f7 NodeId:i-044f03effb64df20d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1664018127984-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:20:40.634321       1 cloud.go:606] Ignoring error from describe volume for volume "vol-07a11f69eb4d91f66"; will retry: "RequestCanceled: request context canceled\ncaused by: context canceled"
I0924 11:20:41.103987       1 cloud.go:492] [Debug] AttachVolume volume="vol-05531c1e5105b97f7" instance="i-044f03effb64df20d" request returned {
  AttachTime: 2022-09-24 11:20:41.088 +0000 UTC,
  Device: "/dev/xvdbb",
  InstanceId: "i-044f03effb64df20d",
  State: "attaching",
  VolumeId: "vol-05531c1e5105b97f7"
}
I0924 11:20:41.156995       1 cloud.go:665] Waiting for volume "vol-05531c1e5105b97f7" state: actual=attaching, desired=attached
I0924 11:20:41.382391       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0b49c944d57bec316 detached from node i-044f03effb64df20d
I0924 11:20:41.406233       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-0b49c944d57bec316 NodeId:i-044f03effb64df20d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:20:41.443555       1 cloud.go:539] DetachDisk called on non-attached volume: vol-0b49c944d57bec316
E0924 11:20:41.520830       1 manager.go:44] Error releasing device: release on device "/dev/xvdbb" assigned to different volume: "vol-0128e220fdf2f6feb" vs "vol-05531c1e5105b97f7"
I0924 11:20:41.520846       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0128e220fdf2f6feb detached from node i-044f03effb64df20d
I0924 11:20:42.222915       1 manager.go:197] [Debug] Releasing in-process attachment entry: /dev/xvdbb -> volume vol-05531c1e5105b97f7
I0924 11:20:42.222931       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-05531c1e5105b97f7 attached to node i-044f03effb64df20d through device /dev/xvdbb
I0924 11:20:42.359244       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0b49c944d57bec316 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:20:42.471341       1 inflight.go:74] Node Service: volume="vol-0b49c944d57bec316" operation finished
I0924 11:20:42.827592       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-0128e220fdf2f6feb Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
... skipping 297 lines ...
I0924 11:21:36.968195       1 controller.go:344] [Debug] ControllerPublishVolume: volume vol-0e0cfc632e22bd237 attached to node i-044f03effb64df20d through device /dev/xvdbd
I0924 11:21:37.469862       1 controller.go:538] CreateSnapshot: called with args source_volume_id:"vol-05531c1e5105b97f7" name:"snapshot-27942132-86ae-4480-9c4e-349b40423b89" 
I0924 11:21:37.515101       1 controller.go:562] Snapshot snapshot-27942132-86ae-4480-9c4e-349b40423b89 of volume vol-05531c1e5105b97f7 already exists; nothing to do
I0924 11:21:37.515118       1 inflight.go:74] Node Service: volume="snapshot-27942132-86ae-4480-9c4e-349b40423b89" operation finished
I0924 11:21:38.136523       1 cloud.go:665] Waiting for volume "vol-0f39f46c3b48abf8f" state: actual=detaching, desired=detached
I0924 11:21:41.506807       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0f39f46c3b48abf8f detached from node i-044f03effb64df20d
W0924 11:21:41.856535       1 cloud.go:606] Ignoring error from describe volume for volume "vol-07a11f69eb4d91f66"; will retry: "RequestCanceled: request context canceled\ncaused by: context canceled"
I0924 11:21:44.831262       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-0815c40986b00936e NodeId:i-044f03effb64df20d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:45.213828       1 cloud.go:665] Waiting for volume "vol-0815c40986b00936e" state: actual=attached, desired=detached
I0924 11:21:46.285688       1 cloud.go:665] Waiting for volume "vol-0815c40986b00936e" state: actual=detaching, desired=detached
I0924 11:21:48.148922       1 cloud.go:665] Waiting for volume "vol-0815c40986b00936e" state: actual=detaching, desired=detached
I0924 11:21:51.170391       1 controller.go:103] CreateVolume: called with args {Name:pvc-842992fe-7296-4ec0-a120-af4fb67346c4 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-842992fe-7296-4ec0-a120-af4fb67346c4 csi.storage.k8s.io/pvc/name:pvc-rjdxw csi.storage.k8s.io/pvc/namespace:ebs-2852 type:gp2] Secrets:map[] VolumeContentSource:snapshot:<snapshot_id:"snap-03bfd9239a9885732" >  AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:21:51.454297       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-0815c40986b00936e detached from node i-044f03effb64df20d
... skipping 67 lines ...
W0924 11:22:27.452976       1 cloud.go:539] DetachDisk called on non-attached volume: vol-05e8502f3f2504abd
I0924 11:22:27.467503       1 inflight.go:74] Node Service: volume="vol-0bb2af696f674dd50" operation finished
I0924 11:22:27.795805       1 controller.go:625] DeleteSnapshot: called with args snapshot_id:"snap-03bfd9239a9885732" 
I0924 11:22:27.977981       1 inflight.go:74] Node Service: volume="snap-03bfd9239a9885732" operation finished
I0924 11:22:33.217339       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:33.344451       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:22:33.344465       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 29c96346-008e-4b9e-a7de-409f006c6d09
I0924 11:22:34.345733       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:34.441838       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:22:34.441868       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 45b607b8-ce96-4848-8005-0b05f8993532
I0924 11:22:36.442716       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:36.528199       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:22:36.528213       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 4fd40fa8-0a3a-4609-8906-1d7b3f42d7f5
I0924 11:22:40.210575       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05e8502f3f2504abd Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:40.358843       1 inflight.go:74] Node Service: volume="vol-05e8502f3f2504abd" operation finished
I0924 11:22:40.529873       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:40.598162       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:22:40.598211       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: b5a82ae0-bcef-4490-b9aa-de1d8a456f13
I0924 11:22:44.869430       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-05f639e0d72202832 NodeId:i-044f03effb64df20d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:45.273934       1 cloud.go:665] Waiting for volume "vol-05f639e0d72202832" state: actual=detaching, desired=detached
I0924 11:22:46.349557       1 cloud.go:665] Waiting for volume "vol-05f639e0d72202832" state: actual=detaching, desired=detached
I0924 11:22:48.213778       1 cloud.go:665] Waiting for volume "vol-05f639e0d72202832" state: actual=detaching, desired=detached
I0924 11:22:48.599868       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:48.675199       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:22:48.675214       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: ca162c7d-9cb1-4e50-9b44-2a389b3f4ff4
I0924 11:22:51.535702       1 controller.go:389] [Debug] ControllerUnpublishVolume: volume vol-05f639e0d72202832 detached from node i-044f03effb64df20d
I0924 11:22:51.550234       1 controller.go:375] ControllerUnpublishVolume: called with args {VolumeId:vol-05f639e0d72202832 NodeId:i-044f03effb64df20d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
W0924 11:22:51.606136       1 cloud.go:539] DetachDisk called on non-attached volume: vol-05f639e0d72202832
I0924 11:22:52.703875       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05f639e0d72202832 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:22:52.852577       1 inflight.go:74] Node Service: volume="vol-05f639e0d72202832" operation finished
I0924 11:23:04.676256       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:23:04.745521       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:23:04.745536       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 04447c50-2be3-4e11-85df-a35ee19f2e7b
W0924 11:23:32.056594       1 cloud.go:606] Ignoring error from describe volume for volume "vol-07a11f69eb4d91f66"; will retry: "RequestCanceled: request context canceled\ncaused by: context canceled"
I0924 11:23:36.746236       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:23:36.831344       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:23:36.831356       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 38dbbf19-5ae5-481e-bc05-53459bb057ae
I0924 11:24:40.832417       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:24:40.933910       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:24:40.933924       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 5efed17f-6cd0-4c71-bc84-4b3952d268bf
I0924 11:26:48.935470       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:26:49.027911       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:26:49.027925       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: c7bdd021-62df-40cb-8dee-1c873c4abd40
W0924 11:26:50.416655       1 cloud.go:606] Ignoring error from describe volume for volume "vol-07a11f69eb4d91f66"; will retry: "RequestCanceled: request context canceled\ncaused by: context canceled"
I0924 11:30:28.102705       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:30:28.188161       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:30:28.188175       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: 1ed7746c-6e4f-4ff9-9203-eecddc035bc4
I0924 11:30:30.240614       1 controller.go:407] ControllerGetCapabilities: called with args {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:30:30.240980       1 controller.go:658] ListSnapshots: called with args snapshot_id:"snap-0fb896988fad04a23" 
I0924 11:31:05.029136       1 controller.go:283] DeleteVolume: called with args: {VolumeId:vol-05531c1e5105b97f7 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:31:05.108113       1 inflight.go:74] Node Service: volume="vol-05531c1e5105b97f7" operation finished
E0924 11:31:05.108130       1 driver.go:120] GRPC error: rpc error: code = Internal desc = Could not delete volume ID "vol-05531c1e5105b97f7": DeleteDisk could not delete volume: VolumeInUse: Volume vol-05531c1e5105b97f7 is currently attached to i-044f03effb64df20d
	status code: 400, request id: c2f20ae7-9691-4eae-a955-8c6e8e48bf92
I0924 11:31:49.223732       1 controller.go:103] CreateVolume: called with args {Name:pvc-620d5df4-e741-46ae-940c-b7fb1c88e7dc CapacityRange:required_bytes:4294967296  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pvc-620d5df4-e741-46ae-940c-b7fb1c88e7dc csi.storage.k8s.io/pvc/name:pvc-lt4cm csi.storage.k8s.io/pvc/namespace:ebs-7796 type:] Secrets:map[] VolumeContentSource:snapshot:<snapshot_id:"snap-0fb896988fad04a23" >  AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-west-2a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:31:52.629184       1 inflight.go:74] Node Service: volume="pvc-620d5df4-e741-46ae-940c-b7fb1c88e7dc" operation finished
I0924 11:31:53.162267       1 controller.go:316] ControllerPublishVolume: called with args {VolumeId:vol-0303a393a5d1037ce NodeId:i-044f03effb64df20d VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1664018127984-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0924 11:31:53.751372       1 cloud.go:492] [Debug] AttachVolume volume="vol-0303a393a5d1037ce" instance="i-044f03effb64df20d" request returned {
  AttachTime: 2022-09-24 11:31:53.733 +0000 UTC,
... skipping 1592 lines ...

Deleted cluster: "test-cluster-25255.k8s.local"
###
## OVERALL_TEST_PASSED: 1
#
###
## FAIL!
#
make: *** [Makefile:157: test-e2e-single-az] 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 ...