kubernetes-sigs/aws-ebs-csi-driver PR #1233 pull-aws-ebs-csi-driver-external-test #1524214280298172416
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | torredil: Use minimal base image for linux builds |
| Result | ABORTED |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 1h0m |
| Revision | 8c58e8c6f178a67a1cec2818ac29dfc28f9cdfc1 |
| Refs |
1233 |
... skipping 609 lines ... ## Validating cluster test-cluster-17276.k8s.local # Using cluster from kubectl context: test-cluster-17276.k8s.local Validating cluster test-cluster-17276.k8s.local W0511 02:28:49.659095 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:28:59.704211 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:29:09.751937 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:29:19.784591 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:29:29.835035 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:29:39.866734 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:29:49.896361 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:30:03.372149 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:30:15.696405 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:30:30.312583 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: Get "https://api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com/api/v1/nodes": dial tcp: lookup api-test-cluster-17276-k8-h54k1k-554014013.us-west-2.elb.amazonaws.com on 10.63.240.10:53: no such host W0511 02:30:51.895191 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: an error on the server ("") has prevented the request from succeeding (get nodes) W0511 02:31:13.428580 9170 validate_cluster.go:173] (will retry): unexpected error during validation: error listing nodes: an error on the server ("") has prevented the request from succeeding (get nodes) 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 7 lines ... Machine i-09b9ec424040aa574 machine "i-09b9ec424040aa574" has not yet joined cluster Machine i-0e18e67b51f251d82 machine "i-0e18e67b51f251d82" has not yet joined cluster Machine i-0fa3de01cd7397db8 machine "i-0fa3de01cd7397db8" has not yet joined cluster Node ip-172-20-43-96.us-west-2.compute.internal node "ip-172-20-43-96.us-west-2.compute.internal" of role "master" is not ready Pod kube-system/kops-controller-5zrqj system-node-critical pod "kops-controller-5zrqj" is pending Validation Failed W0511 02:31:26.169461 9170 validate_cluster.go:221] (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-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-controller-manager pod Node ip-172-20-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-scheduler pod Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is pending Pod kube-system/coredns-autoscaler-6f594f4c58-x95pb system-cluster-critical pod "coredns-autoscaler-6f594f4c58-x95pb" is pending Pod kube-system/dns-controller-5d59c585d8-rsjnk system-cluster-critical pod "dns-controller-5d59c585d8-rsjnk" is pending Validation Failed W0511 02:31:38.608496 9170 validate_cluster.go:221] (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-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-apiserver pod Node ip-172-20-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-controller-manager pod Node ip-172-20-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-scheduler pod Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is pending Pod kube-system/coredns-autoscaler-6f594f4c58-x95pb system-cluster-critical pod "coredns-autoscaler-6f594f4c58-x95pb" is pending Validation Failed W0511 02:31:50.937789 9170 validate_cluster.go:221] (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 13 lines ... Node ip-172-20-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-scheduler pod Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is pending Pod kube-system/coredns-autoscaler-6f594f4c58-x95pb system-cluster-critical pod "coredns-autoscaler-6f594f4c58-x95pb" is pending Pod kube-system/kube-controller-manager-ip-172-20-43-96.us-west-2.compute.internal system-cluster-critical pod "kube-controller-manager-ip-172-20-43-96.us-west-2.compute.internal" is pending Pod kube-system/kube-proxy-ip-172-20-43-96.us-west-2.compute.internal system-node-critical pod "kube-proxy-ip-172-20-43-96.us-west-2.compute.internal" is pending Validation Failed W0511 02:32:03.270864 9170 validate_cluster.go:221] (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-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-apiserver pod Node ip-172-20-43-96.us-west-2.compute.internal master "ip-172-20-43-96.us-west-2.compute.internal" is missing kube-scheduler pod Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is pending Pod kube-system/coredns-autoscaler-6f594f4c58-x95pb system-cluster-critical pod "coredns-autoscaler-6f594f4c58-x95pb" is pending Pod kube-system/etcd-manager-events-ip-172-20-43-96.us-west-2.compute.internal system-cluster-critical pod "etcd-manager-events-ip-172-20-43-96.us-west-2.compute.internal" is pending Validation Failed W0511 02:32:15.777496 9170 validate_cluster.go:221] (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 8 lines ... Machine i-09b9ec424040aa574 machine "i-09b9ec424040aa574" has not yet joined cluster Machine i-0e18e67b51f251d82 machine "i-0e18e67b51f251d82" has not yet joined cluster Machine i-0fa3de01cd7397db8 machine "i-0fa3de01cd7397db8" has not yet joined cluster Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is pending Pod kube-system/coredns-autoscaler-6f594f4c58-x95pb system-cluster-critical pod "coredns-autoscaler-6f594f4c58-x95pb" is pending Validation Failed W0511 02:32:28.030613 9170 validate_cluster.go:221] (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 ... KIND NAME MESSAGE Node ip-172-20-57-178.us-west-2.compute.internal node "ip-172-20-57-178.us-west-2.compute.internal" of role "node" is not ready Node ip-172-20-91-223.us-west-2.compute.internal node "ip-172-20-91-223.us-west-2.compute.internal" of role "node" is not ready Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is pending Pod kube-system/coredns-autoscaler-6f594f4c58-x95pb system-cluster-critical pod "coredns-autoscaler-6f594f4c58-x95pb" is pending Validation Failed W0511 02:32:40.239062 9170 validate_cluster.go:221] (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 8 lines ... VALIDATION ERRORS KIND NAME MESSAGE Pod kube-system/coredns-8f5559c9b-5p2l9 system-cluster-critical pod "coredns-8f5559c9b-5p2l9" is not ready (coredns) Pod kube-system/coredns-8f5559c9b-c4pt9 system-cluster-critical pod "coredns-8f5559c9b-c4pt9" is pending Validation Failed W0511 02:32:52.544549 9170 validate_cluster.go:221] (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 ... ip-172-20-91-223.us-west-2.compute.internal node True VALIDATION ERRORS KIND NAME MESSAGE Pod kube-system/kube-proxy-ip-172-20-57-178.us-west-2.compute.internal system-node-critical pod "kube-proxy-ip-172-20-57-178.us-west-2.compute.internal" is pending Validation Failed W0511 02:33:05.149786 9170 validate_cluster.go:221] (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 101 lines ... [36m[1mS [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Pre-provisioned PV (filesystem volmode)] volumeMode [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [36m[1mshould fail to use a volume in a pod with mismatched mode [Slow] [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297[0m [36mDriver "ebs.csi.aws.com" does not support volume type "PreprovisionedPV" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m ... skipping 50 lines ... [36m[1mS [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Pre-provisioned PV (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [36m[1mshould fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:240[0m [36mDriver "ebs.csi.aws.com" does not support volume type "PreprovisionedPV" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m ... skipping 111 lines ... [36m[1mS [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Pre-provisioned PV (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [36m[1mshould fail if subpath with backstepping is outside the volume [Slow][LinuxOnly] [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:278[0m [36mDriver "ebs.csi.aws.com" does not support volume type "PreprovisionedPV" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m ... skipping 28 lines ... May 11 02:39:59.303: INFO: Waiting for pod external-injector to disappear May 11 02:39:59.368: INFO: Pod external-injector still exists May 11 02:40:01.302: INFO: Waiting for pod external-injector to disappear May 11 02:40:01.367: INFO: Pod external-injector still exists May 11 02:40:03.302: INFO: Waiting for pod external-injector to disappear May 11 02:40:03.366: INFO: Pod external-injector no longer exists May 11 02:40:03.366: FAIL: Failed to create injector pod: timed out waiting for the condition Full Stack Trace k8s.io/kubernetes/test/e2e/storage/testsuites.(*volumesTestSuite).DefineTests.func3() /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:186 +0x485 github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes.TestEBSCSI(0x4082b9?) /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/tests/e2e-kubernetes/e2e_test.go:82 +0x311 ... skipping 17 lines ... May 11 02:40:18.963: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.com7nh8c: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:40:18.963: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.com7nh8c: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "volume-8359/ebs.csi.aws.com7nh8c" May 11 02:40:18.963: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.com7nh8c: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:40:18.963: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for ebs.csi.aws.com7nh8c: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-176169ef-9342-4c2f-8b98-a4a9be441c44 May 11 02:40:18.963: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for external-injector: {default-scheduler } Scheduled: Successfully assigned volume-8359/external-injector to ip-172-20-91-223.us-west-2.compute.internal May 11 02:40:18.963: INFO: At 2022-05-11 02:35:08 +0000 UTC - event for external-injector: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-176169ef-9342-4c2f-8b98-a4a9be441c44" May 11 02:40:18.963: INFO: At 2022-05-11 02:35:10 +0000 UTC - event for external-injector: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-176169ef-9342-4c2f-8b98-a4a9be441c44" : rpc error: code = Internal desc = could not format "/dev/nvme2n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-176169ef-9342-4c2f-8b98-a4a9be441c44/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme2n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-176169ef-9342-4c2f-8b98-a4a9be441c44/globalmount Output: May 11 02:40:18.963: INFO: At 2022-05-11 02:37:04 +0000 UTC - event for external-injector: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[external-volume-0], unattached volumes=[external-volume-0 default-token-d5grf]: timed out waiting for the condition May 11 02:40:19.027: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:40:19.027: INFO: ... skipping 105 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (ext4)] volumes [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould store data [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:159[0m [91mMay 11 02:40:03.366: Failed to create injector pod: timed out waiting for the condition[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:186 [90m------------------------------[0m [36mS[0m[36mS[0m [90m------------------------------[0m [BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath ... skipping 55 lines ... [36mDriver ebs.csi.aws.com doesn't support ntfs -- skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:121 [90m------------------------------[0m [0mExternal Storage [Driver: ebs.csi.aws.com][0m [90m[Testpattern: Dynamic PV (default fs)] subPath[0m [1mshould fail if non-existent subpath is outside the volume [Slow][LinuxOnly][0m [37m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:267[0m [BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 [BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:185 [1mSTEP[0m: Creating a kubernetes client May 11 02:34:54.186: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-17276.k8s.local.kops.kubeconfig [1mSTEP[0m: Building a namespace api object, basename provisioning May 11 02:34:54.652: INFO: No PodSecurityPolicies found; assuming PodSecurityPolicy is disabled. [1mSTEP[0m: 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/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:267 May 11 02:34:54.782: INFO: Creating resource for dynamic PV May 11 02:34:54.782: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass provisioning-860-e2e-sc967dj [1mSTEP[0m: creating a claim May 11 02:34:54.849: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: Creating pod pod-subpath-test-dynamicpv-ndgt [1mSTEP[0m: Checking for subpath error in container status May 11 02:39:55.255: INFO: Deleting pod "pod-subpath-test-dynamicpv-ndgt" in namespace "provisioning-860" May 11 02:39:55.330: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-ndgt" to be fully deleted [1mSTEP[0m: Deleting pod May 11 02:40:03.462: INFO: Deleting pod "pod-subpath-test-dynamicpv-ndgt" in namespace "provisioning-860" [1mSTEP[0m: Deleting pvc May 11 02:40:03.664: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.comxg5v8" ... skipping 14 lines ... May 11 02:40:39.413: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.comxg5v8: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:40:39.413: INFO: At 2022-05-11 02:34:55 +0000 UTC - event for ebs.csi.aws.comxg5v8: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:40:39.413: INFO: At 2022-05-11 02:34:55 +0000 UTC - event for ebs.csi.aws.comxg5v8: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "provisioning-860/ebs.csi.aws.comxg5v8" May 11 02:40:39.413: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for ebs.csi.aws.comxg5v8: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-697bff0a-abc9-4fa7-8281-47a4da4e496a May 11 02:40:39.413: INFO: At 2022-05-11 02:35:02 +0000 UTC - event for pod-subpath-test-dynamicpv-ndgt: {default-scheduler } Scheduled: Successfully assigned provisioning-860/pod-subpath-test-dynamicpv-ndgt to ip-172-20-91-223.us-west-2.compute.internal May 11 02:40:39.413: INFO: At 2022-05-11 02:35:07 +0000 UTC - event for pod-subpath-test-dynamicpv-ndgt: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-697bff0a-abc9-4fa7-8281-47a4da4e496a" May 11 02:40:39.413: INFO: At 2022-05-11 02:35:07 +0000 UTC - event for pod-subpath-test-dynamicpv-ndgt: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-697bff0a-abc9-4fa7-8281-47a4da4e496a" : rpc error: code = Internal desc = could not format "/dev/nvme1n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-697bff0a-abc9-4fa7-8281-47a4da4e496a/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme1n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-697bff0a-abc9-4fa7-8281-47a4da4e496a/globalmount Output: May 11 02:40:39.413: INFO: At 2022-05-11 02:37:05 +0000 UTC - event for pod-subpath-test-dynamicpv-ndgt: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[test-volume liveness-probe-volume default-token-q975f]: timed out waiting for the condition May 11 02:40:39.478: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:40:39.478: INFO: ... skipping 104 lines ... [91m[1m• Failure [347.598 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould fail if non-existent subpath is outside the volume [Slow][LinuxOnly] [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:267[0m [91mwhile waiting for subpath failure Unexpected error: <*errors.errorString | 0xc000ce6e50>: { s: "error waiting for pod subpath error to occur: timed out waiting for the condition", } error waiting for pod subpath error to occur: timed out waiting for the condition occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:718 [90m------------------------------[0m [BeforeEach] [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 ... skipping 108 lines ... May 11 02:44:59.312: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.com9kc8p: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:44:59.312: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.com9kc8p: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:44:59.312: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.com9kc8p: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "fsgroupchangepolicy-3829/ebs.csi.aws.com9kc8p" May 11 02:44:59.312: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for ebs.csi.aws.com9kc8p: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-26c27d61-4506-41a8-892d-8b1fbac10bf5 May 11 02:44:59.312: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {default-scheduler } Scheduled: Successfully assigned fsgroupchangepolicy-3829/pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180 to ip-172-20-91-223.us-west-2.compute.internal May 11 02:44:59.312: INFO: At 2022-05-11 02:35:08 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-26c27d61-4506-41a8-892d-8b1fbac10bf5" May 11 02:44:59.312: INFO: At 2022-05-11 02:35:11 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-26c27d61-4506-41a8-892d-8b1fbac10bf5" : rpc error: code = Internal desc = could not format "/dev/nvme3n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-26c27d61-4506-41a8-892d-8b1fbac10bf5/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme3n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-26c27d61-4506-41a8-892d-8b1fbac10bf5/globalmount Output: May 11 02:44:59.312: INFO: At 2022-05-11 02:37:04 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-tw4hf volume1]: timed out waiting for the condition May 11 02:44:59.312: INFO: At 2022-05-11 02:39:18 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-tw4hf]: timed out waiting for the condition May 11 02:44:59.312: INFO: At 2022-05-11 02:41:49 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-tw4hf volume1]: error processing PVC fsgroupchangepolicy-3829/ebs.csi.aws.com9kc8p: PVC is being deleted May 11 02:44:59.312: INFO: At 2022-05-11 02:42:16 +0000 UTC - event for pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-tw4hf]: error processing PVC fsgroupchangepolicy-3829/ebs.csi.aws.com9kc8p: PVC is being deleted May 11 02:44:59.372: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:44:59.372: INFO: pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180 ip-172-20-91-223.us-west-2.compute.internal Pending [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC }] May 11 02:44:59.373: INFO: May 11 02:44:59.491: INFO: Logging node info for node ip-172-20-119-106.us-west-2.compute.internal May 11 02:44:59.552: INFO: Node Info: &Node{ObjectMeta:{ip-172-20-119-106.us-west-2.compute.internal ff301b1b-3126-4316-af7e-3195f1ee7c08 3186 0 2022-05-11 02:32:36 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:c5.large beta.kubernetes.io/os:linux failure-domain.beta.kubernetes.io/region:us-west-2 failure-domain.beta.kubernetes.io/zone:us-west-2c kops.k8s.io/instancegroup:nodes-us-west-2c kubernetes.io/arch:amd64 kubernetes.io/hostname:ip-172-20-119-106.us-west-2.compute.internal kubernetes.io/os:linux kubernetes.io/role:node node-role.kubernetes.io/node: node.kubernetes.io/instance-type:c5.large topology.ebs.csi.aws.com/zone:us-west-2c topology.kubernetes.io/region:us-west-2 topology.kubernetes.io/zone:us-west-2c] map[csi.volume.kubernetes.io/nodeid:{"ebs.csi.aws.com":"i-09b9ec424040aa574"} node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] [] [{kops-controller Update v1 2022-05-11 02:32:36 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kops.k8s.io/instancegroup":{},"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/node":{}}}}} {kube-controller-manager Update v1 2022-05-11 02:32:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}},"f:spec":{"f:podCIDR":{},"f:podCIDRs":{".":{},"v:\"100.96.2.0/24\"":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"NetworkUnavailable\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}}}}} {kubelet Update v1 2022-05-11 02:33:32 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:csi.volume.kubernetes.io/nodeid":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:topology.ebs.csi.aws.com/zone":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"ExternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"ExternalIP\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:bootID":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}}]},Spec:NodeSpec{PodCIDR:100.96.2.0/24,DoNotUseExternalID:,ProviderID:aws:///us-west-2c/i-09b9ec424040aa574,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[100.96.2.0/24],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{133167038464 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3894337536 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{119850334420 0} {<nil>} 119850334420 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3789479936 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:NetworkUnavailable,Status:False,LastHeartbeatTime:2022-05-11 02:32:44 +0000 UTC,LastTransitionTime:2022-05-11 02:32:44 +0000 UTC,Reason:RouteCreated,Message:RouteController created a route,},NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status. AppArmor enabled,},},Addresses:[]NodeAddress{NodeAddress{Type:InternalIP,Address:172.20.119.106,},NodeAddress{Type:ExternalIP,Address:18.237.55.199,},NodeAddress{Type:Hostname,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:InternalDNS,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:ExternalDNS,Address:ec2-18-237-55-199.us-west-2.compute.amazonaws.com,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ec280ab512dfd6927c9759f5f208afa2,SystemUUID:ec280ab5-12df-d692-7c97-59f5f208afa2,BootID:965afe81-ea15-49ab-83a2-74e8d716b21b,KernelVersion:5.13.0-1021-aws,OSImage:Ubuntu 20.04.4 LTS,ContainerRuntimeVersion:containerd://1.4.6,KubeletVersion:v1.20.8,KubeProxyVersion:v1.20.8,OperatingSystem:linux,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[k8s.gcr.io/kube-proxy@sha256:0c867c82a0a8ce6d093595f9d2e4b10517d6c9c26323075de9d82d9f7d056bfc k8s.gcr.io/kube-proxy:v1.20.8],SizeBytes:52056682,},ContainerImage{Names:[607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver@sha256:7f611863431a70c8da183740f4cb36d5bf5be4e41cf53f27b864c95cd580b91e 607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver:17276],SizeBytes:24201197,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-provisioner@sha256:695505fcfcc69f1cf35665dce487aad447adbb9af69b796d6437f869015d1157 k8s.gcr.io/sig-storage/csi-provisioner:v2.1.1],SizeBytes:21212251,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-attacher@sha256:50c3cfd458fc8e0bf3c8c521eac39172009382fc66dc5044a330d137c6ed0b09 k8s.gcr.io/sig-storage/csi-attacher:v3.1.0],SizeBytes:20103959,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-resizer@sha256:7a5ba58a44e0d749e0767e4e37315bcf6a61f33ce3185c1991848af4db0fb70a k8s.gcr.io/sig-storage/csi-resizer:v1.1.0],SizeBytes:20096832,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-snapshotter@sha256:9af9bf28430b00a0cedeb2ec29acadce45e6afcecd8bdf31c793c624cfa75fa7 k8s.gcr.io/sig-storage/csi-snapshotter:v3.0.3],SizeBytes:19500777,},ContainerImage{Names:[k8s.gcr.io/sig-storage/snapshot-controller@sha256:00fcc441ea9f72899c25eed61d602272a2a58c5f0014332bdcb5ac24acef08e4 k8s.gcr.io/sig-storage/snapshot-controller:v4.0.0],SizeBytes:18952261,},ContainerImage{Names:[k8s.gcr.io/cpa/cluster-proportional-autoscaler@sha256:67640771ad9fc56f109d5b01e020f0c858e7c890bb0eb15ba0ebd325df3285e7 k8s.gcr.io/cpa/cluster-proportional-autoscaler:1.8.3],SizeBytes:15191740,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:a61d309da54641db41fb8f35718f744e9f730d4d0384f8c4b186ddc9f06cbd5f k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.1.0],SizeBytes:9068367,},ContainerImage{Names:[k8s.gcr.io/sig-storage/livenessprobe@sha256:529be2c9770add0cdd0c989115222ea9fc1be430c11095eb9f6dafcf98a36e2b k8s.gcr.io/sig-storage/livenessprobe:v2.4.0],SizeBytes:7960518,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:927d98197ec1141a368550822d18fa1c60bdae27b78b0c004f705f548c07814f k8s.gcr.io/pause:3.2],SizeBytes:299513,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},} ... skipping 106 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1m(OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208[0m [91mUnexpected error: <*errors.errorString | 0xc000836ff0>: { s: "pod \"pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180\" is not Running: timed out waiting for the condition", } pod "pod-31e7b3b7-84a7-48e2-85a4-8b00c2f51180" is not Running: timed out waiting for the condition occurred[0m ... skipping 154 lines ... May 11 02:44:59.386: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.comwbff6: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:44:59.386: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.comwbff6: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:44:59.386: INFO: At 2022-05-11 02:34:54 +0000 UTC - event for ebs.csi.aws.comwbff6: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "fsgroupchangepolicy-703/ebs.csi.aws.comwbff6" May 11 02:44:59.386: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for ebs.csi.aws.comwbff6: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-ae3f79da-c7a2-4b2e-845a-4106b99f953a May 11 02:44:59.386: INFO: At 2022-05-11 02:35:01 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {default-scheduler } Scheduled: Successfully assigned fsgroupchangepolicy-703/pod-45da1e4e-4d2b-48ee-98aa-614595cd714a to ip-172-20-91-223.us-west-2.compute.internal May 11 02:44:59.386: INFO: At 2022-05-11 02:35:08 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-ae3f79da-c7a2-4b2e-845a-4106b99f953a" May 11 02:44:59.386: INFO: At 2022-05-11 02:35:09 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-ae3f79da-c7a2-4b2e-845a-4106b99f953a" : rpc error: code = Internal desc = could not format "/dev/nvme4n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-ae3f79da-c7a2-4b2e-845a-4106b99f953a/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme4n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-ae3f79da-c7a2-4b2e-845a-4106b99f953a/globalmount Output: May 11 02:44:59.386: INFO: At 2022-05-11 02:37:04 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-wshhk volume1]: timed out waiting for the condition May 11 02:44:59.386: INFO: At 2022-05-11 02:39:18 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-wshhk]: timed out waiting for the condition May 11 02:44:59.386: INFO: At 2022-05-11 02:41:50 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-wshhk]: error processing PVC fsgroupchangepolicy-703/ebs.csi.aws.comwbff6: PVC is being deleted May 11 02:44:59.386: INFO: At 2022-05-11 02:42:01 +0000 UTC - event for pod-45da1e4e-4d2b-48ee-98aa-614595cd714a: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-wshhk volume1]: error processing PVC fsgroupchangepolicy-703/ebs.csi.aws.comwbff6: PVC is being deleted May 11 02:44:59.447: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:44:59.447: INFO: pod-45da1e4e-4d2b-48ee-98aa-614595cd714a ip-172-20-91-223.us-west-2.compute.internal Pending [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:35:01 +0000 UTC }] May 11 02:44:59.447: INFO: May 11 02:44:59.569: INFO: Logging node info for node ip-172-20-119-106.us-west-2.compute.internal May 11 02:44:59.633: INFO: Node Info: &Node{ObjectMeta:{ip-172-20-119-106.us-west-2.compute.internal ff301b1b-3126-4316-af7e-3195f1ee7c08 3186 0 2022-05-11 02:32:36 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:c5.large beta.kubernetes.io/os:linux failure-domain.beta.kubernetes.io/region:us-west-2 failure-domain.beta.kubernetes.io/zone:us-west-2c kops.k8s.io/instancegroup:nodes-us-west-2c kubernetes.io/arch:amd64 kubernetes.io/hostname:ip-172-20-119-106.us-west-2.compute.internal kubernetes.io/os:linux kubernetes.io/role:node node-role.kubernetes.io/node: node.kubernetes.io/instance-type:c5.large topology.ebs.csi.aws.com/zone:us-west-2c topology.kubernetes.io/region:us-west-2 topology.kubernetes.io/zone:us-west-2c] map[csi.volume.kubernetes.io/nodeid:{"ebs.csi.aws.com":"i-09b9ec424040aa574"} node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] [] [{kops-controller Update v1 2022-05-11 02:32:36 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kops.k8s.io/instancegroup":{},"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/node":{}}}}} {kube-controller-manager Update v1 2022-05-11 02:32:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}},"f:spec":{"f:podCIDR":{},"f:podCIDRs":{".":{},"v:\"100.96.2.0/24\"":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"NetworkUnavailable\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}}}}} {kubelet Update v1 2022-05-11 02:33:32 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:csi.volume.kubernetes.io/nodeid":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:topology.ebs.csi.aws.com/zone":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"ExternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"ExternalIP\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:bootID":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}}]},Spec:NodeSpec{PodCIDR:100.96.2.0/24,DoNotUseExternalID:,ProviderID:aws:///us-west-2c/i-09b9ec424040aa574,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[100.96.2.0/24],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{133167038464 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3894337536 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{119850334420 0} {<nil>} 119850334420 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3789479936 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:NetworkUnavailable,Status:False,LastHeartbeatTime:2022-05-11 02:32:44 +0000 UTC,LastTransitionTime:2022-05-11 02:32:44 +0000 UTC,Reason:RouteCreated,Message:RouteController created a route,},NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-11 02:44:06 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status. AppArmor enabled,},},Addresses:[]NodeAddress{NodeAddress{Type:InternalIP,Address:172.20.119.106,},NodeAddress{Type:ExternalIP,Address:18.237.55.199,},NodeAddress{Type:Hostname,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:InternalDNS,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:ExternalDNS,Address:ec2-18-237-55-199.us-west-2.compute.amazonaws.com,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ec280ab512dfd6927c9759f5f208afa2,SystemUUID:ec280ab5-12df-d692-7c97-59f5f208afa2,BootID:965afe81-ea15-49ab-83a2-74e8d716b21b,KernelVersion:5.13.0-1021-aws,OSImage:Ubuntu 20.04.4 LTS,ContainerRuntimeVersion:containerd://1.4.6,KubeletVersion:v1.20.8,KubeProxyVersion:v1.20.8,OperatingSystem:linux,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[k8s.gcr.io/kube-proxy@sha256:0c867c82a0a8ce6d093595f9d2e4b10517d6c9c26323075de9d82d9f7d056bfc k8s.gcr.io/kube-proxy:v1.20.8],SizeBytes:52056682,},ContainerImage{Names:[607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver@sha256:7f611863431a70c8da183740f4cb36d5bf5be4e41cf53f27b864c95cd580b91e 607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver:17276],SizeBytes:24201197,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-provisioner@sha256:695505fcfcc69f1cf35665dce487aad447adbb9af69b796d6437f869015d1157 k8s.gcr.io/sig-storage/csi-provisioner:v2.1.1],SizeBytes:21212251,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-attacher@sha256:50c3cfd458fc8e0bf3c8c521eac39172009382fc66dc5044a330d137c6ed0b09 k8s.gcr.io/sig-storage/csi-attacher:v3.1.0],SizeBytes:20103959,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-resizer@sha256:7a5ba58a44e0d749e0767e4e37315bcf6a61f33ce3185c1991848af4db0fb70a k8s.gcr.io/sig-storage/csi-resizer:v1.1.0],SizeBytes:20096832,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-snapshotter@sha256:9af9bf28430b00a0cedeb2ec29acadce45e6afcecd8bdf31c793c624cfa75fa7 k8s.gcr.io/sig-storage/csi-snapshotter:v3.0.3],SizeBytes:19500777,},ContainerImage{Names:[k8s.gcr.io/sig-storage/snapshot-controller@sha256:00fcc441ea9f72899c25eed61d602272a2a58c5f0014332bdcb5ac24acef08e4 k8s.gcr.io/sig-storage/snapshot-controller:v4.0.0],SizeBytes:18952261,},ContainerImage{Names:[k8s.gcr.io/cpa/cluster-proportional-autoscaler@sha256:67640771ad9fc56f109d5b01e020f0c858e7c890bb0eb15ba0ebd325df3285e7 k8s.gcr.io/cpa/cluster-proportional-autoscaler:1.8.3],SizeBytes:15191740,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:a61d309da54641db41fb8f35718f744e9f730d4d0384f8c4b186ddc9f06cbd5f k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.1.0],SizeBytes:9068367,},ContainerImage{Names:[k8s.gcr.io/sig-storage/livenessprobe@sha256:529be2c9770add0cdd0c989115222ea9fc1be430c11095eb9f6dafcf98a36e2b k8s.gcr.io/sig-storage/livenessprobe:v2.4.0],SizeBytes:7960518,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:927d98197ec1141a368550822d18fa1c60bdae27b78b0c004f705f548c07814f k8s.gcr.io/pause:3.2],SizeBytes:299513,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},} ... skipping 106 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1m(Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208[0m [91mUnexpected error: <*errors.errorString | 0xc000381190>: { s: "pod \"pod-45da1e4e-4d2b-48ee-98aa-614595cd714a\" is not Running: timed out waiting for the condition", } pod "pod-45da1e4e-4d2b-48ee-98aa-614595cd714a" is not Running: timed out waiting for the condition occurred[0m ... skipping 17 lines ... May 11 02:40:21.663: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass volume-3915-e2e-sc6nvzg [1mSTEP[0m: creating a claim May 11 02:40:21.728: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: Creating pod exec-volume-test-dynamicpv-glvq [1mSTEP[0m: Creating a pod to test exec-volume-test May 11 02:40:21.926: INFO: Waiting up to 5m0s for pod "exec-volume-test-dynamicpv-glvq" in namespace "volume-3915" to be "Succeeded or Failed" May 11 02:40:21.993: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 66.677754ms May 11 02:40:24.057: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 2.131470474s May 11 02:40:26.123: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4.196622291s May 11 02:40:28.189: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 6.263269495s May 11 02:40:30.254: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 8.328254231s May 11 02:40:32.320: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 10.394333625s ... skipping 134 lines ... May 11 02:45:11.262: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4m49.335548064s May 11 02:45:13.327: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4m51.401389782s May 11 02:45:15.393: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4m53.46684569s May 11 02:45:17.459: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4m55.532478367s May 11 02:45:19.524: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4m57.598038735s May 11 02:45:21.589: INFO: Pod "exec-volume-test-dynamicpv-glvq": Phase="Pending", Reason="", readiness=false. Elapsed: 4m59.663116783s May 11 02:45:23.733: INFO: Failed to get logs from node "ip-172-20-91-223.us-west-2.compute.internal" pod "exec-volume-test-dynamicpv-glvq" container "exec-container-dynamicpv-glvq": the server rejected our request for an unknown reason (get pods exec-volume-test-dynamicpv-glvq) [1mSTEP[0m: delete the pod May 11 02:45:23.799: INFO: Waiting for pod exec-volume-test-dynamicpv-glvq to disappear May 11 02:45:23.863: INFO: Pod exec-volume-test-dynamicpv-glvq still exists May 11 02:45:25.864: INFO: Waiting for pod exec-volume-test-dynamicpv-glvq to disappear May 11 02:45:25.929: INFO: Pod exec-volume-test-dynamicpv-glvq still exists May 11 02:45:27.863: INFO: Waiting for pod exec-volume-test-dynamicpv-glvq to disappear ... skipping 19 lines ... May 11 02:45:49.516: INFO: At 2022-05-11 02:40:21 +0000 UTC - event for ebs.csi.aws.com2nrnb: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:45:49.516: INFO: At 2022-05-11 02:40:21 +0000 UTC - event for ebs.csi.aws.com2nrnb: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:45:49.516: INFO: At 2022-05-11 02:40:21 +0000 UTC - event for ebs.csi.aws.com2nrnb: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "volume-3915/ebs.csi.aws.com2nrnb" May 11 02:45:49.516: INFO: At 2022-05-11 02:40:25 +0000 UTC - event for ebs.csi.aws.com2nrnb: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-83422518-b5f0-424f-8348-407348828704 May 11 02:45:49.516: INFO: At 2022-05-11 02:40:25 +0000 UTC - event for exec-volume-test-dynamicpv-glvq: {default-scheduler } Scheduled: Successfully assigned volume-3915/exec-volume-test-dynamicpv-glvq to ip-172-20-91-223.us-west-2.compute.internal May 11 02:45:49.516: INFO: At 2022-05-11 02:40:28 +0000 UTC - event for exec-volume-test-dynamicpv-glvq: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-83422518-b5f0-424f-8348-407348828704" May 11 02:45:49.516: INFO: At 2022-05-11 02:40:29 +0000 UTC - event for exec-volume-test-dynamicpv-glvq: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-83422518-b5f0-424f-8348-407348828704" : rpc error: code = Internal desc = could not format "/dev/nvme1n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-83422518-b5f0-424f-8348-407348828704/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme1n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-83422518-b5f0-424f-8348-407348828704/globalmount Output: May 11 02:45:49.516: INFO: At 2022-05-11 02:42:28 +0000 UTC - event for exec-volume-test-dynamicpv-glvq: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[vol1], unattached volumes=[vol1 default-token-mb8nd]: timed out waiting for the condition May 11 02:45:49.580: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:45:49.580: INFO: ... skipping 107 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (ext4)] volumes [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould allow exec of files on the volume [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumes.go:196[0m [91mUnexpected error: <*errors.errorString | 0xc000e375c0>: { s: "expected pod \"exec-volume-test-dynamicpv-glvq\" success: Gave up after waiting 5m0s for pod \"exec-volume-test-dynamicpv-glvq\" to be \"Succeeded or Failed\"", } expected pod "exec-volume-test-dynamicpv-glvq" success: Gave up after waiting 5m0s for pod "exec-volume-test-dynamicpv-glvq" to be "Succeeded or Failed" occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/util.go:742 [90m------------------------------[0m [36mS[0m[36mS[0m[36mS[0m [90m------------------------------[0m ... skipping 34 lines ... May 11 02:46:05.335: INFO: At 2022-05-11 02:40:42 +0000 UTC - event for pod-3b8773ef-7d17-4fb2-a66b-68b10c8d6c88: {default-scheduler } FailedScheduling: 0/4 nodes are available: 4 pod has unbound immediate PersistentVolumeClaims. May 11 02:46:05.335: INFO: At 2022-05-11 02:40:42 +0000 UTC - event for pvc-7mz6q: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:46:05.335: INFO: At 2022-05-11 02:40:42 +0000 UTC - event for pvc-7mz6q: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "topology-3240/pvc-7mz6q" May 11 02:46:05.335: INFO: At 2022-05-11 02:40:45 +0000 UTC - event for pvc-7mz6q: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-e9e7cf67-d943-40f9-9509-9dc7ac127d56 May 11 02:46:05.335: INFO: At 2022-05-11 02:40:50 +0000 UTC - event for pod-3b8773ef-7d17-4fb2-a66b-68b10c8d6c88: {default-scheduler } Scheduled: Successfully assigned topology-3240/pod-3b8773ef-7d17-4fb2-a66b-68b10c8d6c88 to ip-172-20-57-178.us-west-2.compute.internal May 11 02:46:05.335: INFO: At 2022-05-11 02:40:52 +0000 UTC - event for pod-3b8773ef-7d17-4fb2-a66b-68b10c8d6c88: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-e9e7cf67-d943-40f9-9509-9dc7ac127d56" May 11 02:46:05.335: INFO: At 2022-05-11 02:40:58 +0000 UTC - event for pod-3b8773ef-7d17-4fb2-a66b-68b10c8d6c88: {kubelet ip-172-20-57-178.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-e9e7cf67-d943-40f9-9509-9dc7ac127d56" : rpc error: code = Internal desc = could not format "/dev/nvme1n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-e9e7cf67-d943-40f9-9509-9dc7ac127d56/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme1n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-e9e7cf67-d943-40f9-9509-9dc7ac127d56/globalmount Output: May 11 02:46:05.336: INFO: At 2022-05-11 02:42:53 +0000 UTC - event for pod-3b8773ef-7d17-4fb2-a66b-68b10c8d6c88: {kubelet ip-172-20-57-178.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-pv4f6]: timed out waiting for the condition May 11 02:46:05.401: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:46:05.401: INFO: ... skipping 108 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (immediate binding)] topology [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould provision a volume and schedule a pod with AllowedTopologies [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/topology.go:164[0m [91mUnexpected error: <*errors.errorString | 0xc00022e200>: { s: "timed out waiting for the condition", } timed out waiting for the condition occurred[0m ... skipping 50 lines ... [36mDriver "ebs.csi.aws.com" does not support volume type "CSIInlineVolume" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m [0mExternal Storage [Driver: ebs.csi.aws.com][0m [90m[Testpattern: Dynamic PV (block volmode)] volumeMode[0m [1mshould fail to use a volume in a pod with mismatched mode [Slow][0m [37m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297[0m [BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 [BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:185 [1mSTEP[0m: Creating a kubernetes client May 11 02:46:08.073: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-17276.k8s.local.kops.kubeconfig [1mSTEP[0m: Building a namespace api object, basename volumemode [1mSTEP[0m: 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/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297 May 11 02:46:08.401: INFO: Creating resource for dynamic PV May 11 02:46:08.401: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass volumemode-1134-e2e-scb42px [1mSTEP[0m: creating a claim [1mSTEP[0m: Creating pod [1mSTEP[0m: Waiting for the pod to fail May 11 02:46:14.872: INFO: Deleting pod "pod-de7f4f12-9443-4a2a-8e2a-812cde8b1bf6" in namespace "volumemode-1134" May 11 02:46:14.940: INFO: Wait up to 5m0s for pod "pod-de7f4f12-9443-4a2a-8e2a-812cde8b1bf6" to be fully deleted [1mSTEP[0m: Deleting pvc May 11 02:46:23.206: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.com47mlm" May 11 02:46:23.275: INFO: Waiting up to 5m0s for PersistentVolume pvc-8e1fe51b-a215-48bd-b09c-5aa87b0e406b to get deleted May 11 02:46:23.341: INFO: PersistentVolume pvc-8e1fe51b-a215-48bd-b09c-5aa87b0e406b found and phase=Released (65.539959ms) ... skipping 7 lines ... [32m• [SLOW TEST:20.539 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (block volmode)] volumeMode [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m should fail to use a volume in a pod with mismatched mode [Slow] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297[0m [90m------------------------------[0m [BeforeEach] [Testpattern: Pre-provisioned PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 May 11 02:46:28.614: INFO: Driver "ebs.csi.aws.com" does not support volume type "PreprovisionedPV" - skipping [AfterEach] [Testpattern: Pre-provisioned PV (default fs)] subPath ... skipping 42 lines ... [36m[1mS [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Inline-volume (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [36m[1mshould fail if subpath file is outside the volume [Slow][LinuxOnly] [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:256[0m [36mDriver "ebs.csi.aws.com" does not support volume type "InlineVolume" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m ... skipping 110 lines ... May 11 02:45:52.120: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: starting external-io-client [1mSTEP[0m: deleting test file /opt/external-volumeio-6493-dd_if... May 11 02:50:52.517: INFO: ExecWithOptions {Command:[/bin/sh -c rm -f /opt/external-volumeio-6493-dd_if] Namespace:volumeio-6493 PodName:external-io-client ContainerName:external-io-client Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false} May 11 02:50:52.517: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-17276.k8s.local.kops.kubeconfig May 11 02:50:52.756: INFO: unable to delete test file /opt/external-volumeio-6493-dd_if: unable to upgrade connection: container not found ("external-io-client") error ignored, continuing test stdout: stderr: [1mSTEP[0m: deleting client pod "external-io-client"... May 11 02:50:52.756: INFO: Deleting pod "external-io-client" in namespace "volumeio-6493" May 11 02:50:52.825: INFO: Wait up to 5m0s for pod "external-io-client" to be fully deleted May 11 02:51:02.954: INFO: sleeping a bit so kubelet can unmount and detach the volume ... skipping 10 lines ... May 11 02:51:28.428: INFO: At 2022-05-11 02:45:52 +0000 UTC - event for ebs.csi.aws.com5wfzk: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:51:28.428: INFO: At 2022-05-11 02:45:52 +0000 UTC - event for ebs.csi.aws.com5wfzk: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:51:28.428: INFO: At 2022-05-11 02:45:52 +0000 UTC - event for ebs.csi.aws.com5wfzk: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "volumeio-6493/ebs.csi.aws.com5wfzk" May 11 02:51:28.428: INFO: At 2022-05-11 02:45:55 +0000 UTC - event for ebs.csi.aws.com5wfzk: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-6f2af7f8-9fb9-4ed2-9d3c-1a5da78ba186 May 11 02:51:28.428: INFO: At 2022-05-11 02:45:56 +0000 UTC - event for external-io-client: {default-scheduler } Scheduled: Successfully assigned volumeio-6493/external-io-client to ip-172-20-91-223.us-west-2.compute.internal May 11 02:51:28.428: INFO: At 2022-05-11 02:45:58 +0000 UTC - event for external-io-client: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-6f2af7f8-9fb9-4ed2-9d3c-1a5da78ba186" May 11 02:51:28.428: INFO: At 2022-05-11 02:46:00 +0000 UTC - event for external-io-client: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-6f2af7f8-9fb9-4ed2-9d3c-1a5da78ba186" : rpc error: code = Internal desc = could not format "/dev/nvme1n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6f2af7f8-9fb9-4ed2-9d3c-1a5da78ba186/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme1n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6f2af7f8-9fb9-4ed2-9d3c-1a5da78ba186/globalmount Output: May 11 02:51:28.428: INFO: At 2022-05-11 02:47:59 +0000 UTC - event for external-io-client: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[io-volume-volumeio-6493], unattached volumes=[default-token-26nqh io-volume-volumeio-6493]: timed out waiting for the condition May 11 02:51:28.492: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:51:28.492: INFO: ... skipping 107 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] volumeIO [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould write files of various sizes, verify size, validate content [Slow][LinuxOnly] [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_io.go:146[0m [91mUnexpected error: <*errors.errorString | 0xc001286b60>: { s: "client pod \"external-io-client\" not running: timed out waiting for the condition", } client pod "external-io-client" not running: timed out waiting for the condition occurred[0m ... skipping 64 lines ... May 11 02:51:49.765: INFO: At 2022-05-11 02:46:29 +0000 UTC - event for ebs.csi.aws.comz24jf: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:51:49.765: INFO: At 2022-05-11 02:46:29 +0000 UTC - event for ebs.csi.aws.comz24jf: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:51:49.765: INFO: At 2022-05-11 02:46:29 +0000 UTC - event for ebs.csi.aws.comz24jf: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "multivolume-7069/ebs.csi.aws.comz24jf" May 11 02:51:49.765: INFO: At 2022-05-11 02:46:33 +0000 UTC - event for ebs.csi.aws.comz24jf: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-3d37ee30-2c00-42a1-ae75-657f292f988b May 11 02:51:49.765: INFO: At 2022-05-11 02:46:33 +0000 UTC - event for pod-2edadb36-24a0-4f86-9bf3-6b201128b381: {default-scheduler } Scheduled: Successfully assigned multivolume-7069/pod-2edadb36-24a0-4f86-9bf3-6b201128b381 to ip-172-20-91-223.us-west-2.compute.internal May 11 02:51:49.765: INFO: At 2022-05-11 02:46:35 +0000 UTC - event for pod-2edadb36-24a0-4f86-9bf3-6b201128b381: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-3d37ee30-2c00-42a1-ae75-657f292f988b" May 11 02:51:49.765: INFO: At 2022-05-11 02:46:37 +0000 UTC - event for pod-2edadb36-24a0-4f86-9bf3-6b201128b381: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMapVolume: MapVolume.MapPodDevice failed for volume "pvc-3d37ee30-2c00-42a1-ae75-657f292f988b" : rpc error: code = Internal desc = Could not mount "/dev/nvme3n1" at "/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/publish/pvc-3d37ee30-2c00-42a1-ae75-657f292f988b/e0589928-f141-4ca3-840b-d2cccd7397b6": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -o bind /dev/nvme3n1 /var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/publish/pvc-3d37ee30-2c00-42a1-ae75-657f292f988b/e0589928-f141-4ca3-840b-d2cccd7397b6 Output: May 11 02:51:49.765: INFO: At 2022-05-11 02:48:36 +0000 UTC - event for pod-2edadb36-24a0-4f86-9bf3-6b201128b381: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-5p2qj volume1]: timed out waiting for the condition May 11 02:51:49.830: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:51:49.830: INFO: ... skipping 107 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (block volmode)] multiVolume [Slow] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould concurrently access the single volume from pods on the same node [LinuxOnly] [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/multivolume.go:312[0m [91mUnexpected error: <*errors.errorString | 0xc0009fe0d0>: { s: "pod \"pod-2edadb36-24a0-4f86-9bf3-6b201128b381\" is not Running: timed out waiting for the condition", } pod "pod-2edadb36-24a0-4f86-9bf3-6b201128b381" is not Running: timed out waiting for the condition occurred[0m ... skipping 109 lines ... May 11 02:55:06.609: INFO: At 2022-05-11 02:45:02 +0000 UTC - event for ebs.csi.aws.comm9t5g: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:55:06.609: INFO: At 2022-05-11 02:45:02 +0000 UTC - event for ebs.csi.aws.comm9t5g: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:55:06.609: INFO: At 2022-05-11 02:45:02 +0000 UTC - event for ebs.csi.aws.comm9t5g: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "fsgroupchangepolicy-2479/ebs.csi.aws.comm9t5g" May 11 02:55:06.609: INFO: At 2022-05-11 02:45:05 +0000 UTC - event for ebs.csi.aws.comm9t5g: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-8deefd03-21f0-4e8c-950d-604c5c6e5e6e May 11 02:55:06.609: INFO: At 2022-05-11 02:45:06 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {default-scheduler } Scheduled: Successfully assigned fsgroupchangepolicy-2479/pod-04e22657-bf38-4ef6-bf87-96d82bec5713 to ip-172-20-91-223.us-west-2.compute.internal May 11 02:55:06.609: INFO: At 2022-05-11 02:45:10 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-8deefd03-21f0-4e8c-950d-604c5c6e5e6e" May 11 02:55:06.609: INFO: At 2022-05-11 02:45:14 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-8deefd03-21f0-4e8c-950d-604c5c6e5e6e" : rpc error: code = Internal desc = could not format "/dev/nvme5n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-8deefd03-21f0-4e8c-950d-604c5c6e5e6e/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme5n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-8deefd03-21f0-4e8c-950d-604c5c6e5e6e/globalmount Output: May 11 02:55:06.609: INFO: At 2022-05-11 02:47:09 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-dg7rh volume1]: timed out waiting for the condition May 11 02:55:06.609: INFO: At 2022-05-11 02:49:26 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-dg7rh]: timed out waiting for the condition May 11 02:55:06.609: INFO: At 2022-05-11 02:51:55 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-dg7rh volume1]: error processing PVC fsgroupchangepolicy-2479/ebs.csi.aws.comm9t5g: PVC is being deleted May 11 02:55:06.609: INFO: At 2022-05-11 02:52:08 +0000 UTC - event for pod-04e22657-bf38-4ef6-bf87-96d82bec5713: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-dg7rh]: error processing PVC fsgroupchangepolicy-2479/ebs.csi.aws.comm9t5g: PVC is being deleted May 11 02:55:06.672: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:55:06.672: INFO: pod-04e22657-bf38-4ef6-bf87-96d82bec5713 ip-172-20-91-223.us-west-2.compute.internal Pending [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC }] May 11 02:55:06.672: INFO: May 11 02:55:06.733: INFO: Logging node info for node ip-172-20-119-106.us-west-2.compute.internal May 11 02:55:06.794: INFO: Node Info: &Node{ObjectMeta:{ip-172-20-119-106.us-west-2.compute.internal ff301b1b-3126-4316-af7e-3195f1ee7c08 5493 0 2022-05-11 02:32:36 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:c5.large beta.kubernetes.io/os:linux failure-domain.beta.kubernetes.io/region:us-west-2 failure-domain.beta.kubernetes.io/zone:us-west-2c kops.k8s.io/instancegroup:nodes-us-west-2c kubernetes.io/arch:amd64 kubernetes.io/hostname:ip-172-20-119-106.us-west-2.compute.internal kubernetes.io/os:linux kubernetes.io/role:node node-role.kubernetes.io/node: node.kubernetes.io/instance-type:c5.large topology.ebs.csi.aws.com/zone:us-west-2c topology.kubernetes.io/region:us-west-2 topology.kubernetes.io/zone:us-west-2c] map[csi.volume.kubernetes.io/nodeid:{"ebs.csi.aws.com":"i-09b9ec424040aa574"} node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] [] [{kops-controller Update v1 2022-05-11 02:32:36 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kops.k8s.io/instancegroup":{},"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/node":{}}}}} {kube-controller-manager Update v1 2022-05-11 02:32:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}},"f:spec":{"f:podCIDR":{},"f:podCIDRs":{".":{},"v:\"100.96.2.0/24\"":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"NetworkUnavailable\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}}}}} {kubelet Update v1 2022-05-11 02:33:32 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:csi.volume.kubernetes.io/nodeid":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:topology.ebs.csi.aws.com/zone":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"ExternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"ExternalIP\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:bootID":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}}]},Spec:NodeSpec{PodCIDR:100.96.2.0/24,DoNotUseExternalID:,ProviderID:aws:///us-west-2c/i-09b9ec424040aa574,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[100.96.2.0/24],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{133167038464 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3894337536 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{119850334420 0} {<nil>} 119850334420 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3789479936 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:NetworkUnavailable,Status:False,LastHeartbeatTime:2022-05-11 02:32:44 +0000 UTC,LastTransitionTime:2022-05-11 02:32:44 +0000 UTC,Reason:RouteCreated,Message:RouteController created a route,},NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status. AppArmor enabled,},},Addresses:[]NodeAddress{NodeAddress{Type:InternalIP,Address:172.20.119.106,},NodeAddress{Type:ExternalIP,Address:18.237.55.199,},NodeAddress{Type:Hostname,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:InternalDNS,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:ExternalDNS,Address:ec2-18-237-55-199.us-west-2.compute.amazonaws.com,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ec280ab512dfd6927c9759f5f208afa2,SystemUUID:ec280ab5-12df-d692-7c97-59f5f208afa2,BootID:965afe81-ea15-49ab-83a2-74e8d716b21b,KernelVersion:5.13.0-1021-aws,OSImage:Ubuntu 20.04.4 LTS,ContainerRuntimeVersion:containerd://1.4.6,KubeletVersion:v1.20.8,KubeProxyVersion:v1.20.8,OperatingSystem:linux,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[k8s.gcr.io/kube-proxy@sha256:0c867c82a0a8ce6d093595f9d2e4b10517d6c9c26323075de9d82d9f7d056bfc k8s.gcr.io/kube-proxy:v1.20.8],SizeBytes:52056682,},ContainerImage{Names:[607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver@sha256:7f611863431a70c8da183740f4cb36d5bf5be4e41cf53f27b864c95cd580b91e 607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver:17276],SizeBytes:24201197,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-provisioner@sha256:695505fcfcc69f1cf35665dce487aad447adbb9af69b796d6437f869015d1157 k8s.gcr.io/sig-storage/csi-provisioner:v2.1.1],SizeBytes:21212251,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-attacher@sha256:50c3cfd458fc8e0bf3c8c521eac39172009382fc66dc5044a330d137c6ed0b09 k8s.gcr.io/sig-storage/csi-attacher:v3.1.0],SizeBytes:20103959,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-resizer@sha256:7a5ba58a44e0d749e0767e4e37315bcf6a61f33ce3185c1991848af4db0fb70a k8s.gcr.io/sig-storage/csi-resizer:v1.1.0],SizeBytes:20096832,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-snapshotter@sha256:9af9bf28430b00a0cedeb2ec29acadce45e6afcecd8bdf31c793c624cfa75fa7 k8s.gcr.io/sig-storage/csi-snapshotter:v3.0.3],SizeBytes:19500777,},ContainerImage{Names:[k8s.gcr.io/sig-storage/snapshot-controller@sha256:00fcc441ea9f72899c25eed61d602272a2a58c5f0014332bdcb5ac24acef08e4 k8s.gcr.io/sig-storage/snapshot-controller:v4.0.0],SizeBytes:18952261,},ContainerImage{Names:[k8s.gcr.io/cpa/cluster-proportional-autoscaler@sha256:67640771ad9fc56f109d5b01e020f0c858e7c890bb0eb15ba0ebd325df3285e7 k8s.gcr.io/cpa/cluster-proportional-autoscaler:1.8.3],SizeBytes:15191740,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:a61d309da54641db41fb8f35718f744e9f730d4d0384f8c4b186ddc9f06cbd5f k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.1.0],SizeBytes:9068367,},ContainerImage{Names:[k8s.gcr.io/sig-storage/livenessprobe@sha256:529be2c9770add0cdd0c989115222ea9fc1be430c11095eb9f6dafcf98a36e2b k8s.gcr.io/sig-storage/livenessprobe:v2.4.0],SizeBytes:7960518,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:927d98197ec1141a368550822d18fa1c60bdae27b78b0c004f705f548c07814f k8s.gcr.io/pause:3.2],SizeBytes:299513,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},} ... skipping 106 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1m(OnRootMismatch)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with different fsgroup applied to the volume contents [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208[0m [91mUnexpected error: <*errors.errorString | 0xc00092f950>: { s: "pod \"pod-04e22657-bf38-4ef6-bf87-96d82bec5713\" is not Running: timed out waiting for the condition", } pod "pod-04e22657-bf38-4ef6-bf87-96d82bec5713" is not Running: timed out waiting for the condition occurred[0m ... skipping 87 lines ... May 11 02:45:01.842: INFO: Creating resource for dynamic PV May 11 02:45:01.842: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass provisioning-7117-e2e-scfmc5g [1mSTEP[0m: creating a claim May 11 02:45:01.908: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: Creating pod to format volume volume-prep-provisioning-7117 May 11 02:45:02.110: INFO: Waiting up to 5m0s for pod "volume-prep-provisioning-7117" in namespace "provisioning-7117" to be "Succeeded or Failed" May 11 02:45:02.171: INFO: Pod "volume-prep-provisioning-7117": Phase="Pending", Reason="", readiness=false. Elapsed: 60.94207ms May 11 02:45:04.243: INFO: Pod "volume-prep-provisioning-7117": Phase="Pending", Reason="", readiness=false. Elapsed: 2.133303503s May 11 02:45:06.309: INFO: Pod "volume-prep-provisioning-7117": Phase="Pending", Reason="", readiness=false. Elapsed: 4.19883401s May 11 02:45:08.370: INFO: Pod "volume-prep-provisioning-7117": Phase="Pending", Reason="", readiness=false. Elapsed: 6.260240232s May 11 02:45:10.433: INFO: Pod "volume-prep-provisioning-7117": Phase="Pending", Reason="", readiness=false. Elapsed: 8.322503855s May 11 02:45:12.494: INFO: Pod "volume-prep-provisioning-7117": Phase="Pending", Reason="", readiness=false. Elapsed: 10.383497887s ... skipping 210 lines ... May 11 02:55:07.229: INFO: At 2022-05-11 02:45:01 +0000 UTC - event for ebs.csi.aws.comjfppk: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 02:55:07.229: INFO: At 2022-05-11 02:45:02 +0000 UTC - event for ebs.csi.aws.comjfppk: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 02:55:07.229: INFO: At 2022-05-11 02:45:02 +0000 UTC - event for ebs.csi.aws.comjfppk: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "provisioning-7117/ebs.csi.aws.comjfppk" May 11 02:55:07.229: INFO: At 2022-05-11 02:45:05 +0000 UTC - event for ebs.csi.aws.comjfppk: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-5550b97c-05f5-4a09-bd9b-3682c0f7e748 May 11 02:55:07.229: INFO: At 2022-05-11 02:45:06 +0000 UTC - event for volume-prep-provisioning-7117: {default-scheduler } Scheduled: Successfully assigned provisioning-7117/volume-prep-provisioning-7117 to ip-172-20-91-223.us-west-2.compute.internal May 11 02:55:07.229: INFO: At 2022-05-11 02:45:08 +0000 UTC - event for volume-prep-provisioning-7117: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-5550b97c-05f5-4a09-bd9b-3682c0f7e748" May 11 02:55:07.229: INFO: At 2022-05-11 02:45:10 +0000 UTC - event for volume-prep-provisioning-7117: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-5550b97c-05f5-4a09-bd9b-3682c0f7e748" : rpc error: code = Internal desc = could not format "/dev/nvme2n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-5550b97c-05f5-4a09-bd9b-3682c0f7e748/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme2n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-5550b97c-05f5-4a09-bd9b-3682c0f7e748/globalmount Output: May 11 02:55:07.229: INFO: At 2022-05-11 02:47:09 +0000 UTC - event for volume-prep-provisioning-7117: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[default-token-4mxq4 test-volume]: timed out waiting for the condition May 11 02:55:07.229: INFO: At 2022-05-11 02:51:42 +0000 UTC - event for volume-prep-provisioning-7117: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[test-volume default-token-4mxq4]: timed out waiting for the condition May 11 02:55:07.229: INFO: At 2022-05-11 02:51:57 +0000 UTC - event for volume-prep-provisioning-7117: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[test-volume default-token-4mxq4]: error processing PVC provisioning-7117/ebs.csi.aws.comjfppk: PVC is being deleted May 11 02:55:07.229: INFO: At 2022-05-11 02:52:12 +0000 UTC - event for volume-prep-provisioning-7117: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[default-token-4mxq4 test-volume]: error processing PVC provisioning-7117/ebs.csi.aws.comjfppk: PVC is being deleted May 11 02:55:07.289: INFO: POD NODE PHASE GRACE CONDITIONS May 11 02:55:07.289: INFO: volume-prep-provisioning-7117 ip-172-20-91-223.us-west-2.compute.internal Pending [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC ContainersNotReady containers with unready status: [init-volume-provisioning-7117]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC ContainersNotReady containers with unready status: [init-volume-provisioning-7117]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 02:45:06 +0000 UTC }] May 11 02:55:07.289: INFO: May 11 02:55:07.351: INFO: Logging node info for node ip-172-20-119-106.us-west-2.compute.internal May 11 02:55:07.410: INFO: Node Info: &Node{ObjectMeta:{ip-172-20-119-106.us-west-2.compute.internal ff301b1b-3126-4316-af7e-3195f1ee7c08 5493 0 2022-05-11 02:32:36 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:c5.large beta.kubernetes.io/os:linux failure-domain.beta.kubernetes.io/region:us-west-2 failure-domain.beta.kubernetes.io/zone:us-west-2c kops.k8s.io/instancegroup:nodes-us-west-2c kubernetes.io/arch:amd64 kubernetes.io/hostname:ip-172-20-119-106.us-west-2.compute.internal kubernetes.io/os:linux kubernetes.io/role:node node-role.kubernetes.io/node: node.kubernetes.io/instance-type:c5.large topology.ebs.csi.aws.com/zone:us-west-2c topology.kubernetes.io/region:us-west-2 topology.kubernetes.io/zone:us-west-2c] map[csi.volume.kubernetes.io/nodeid:{"ebs.csi.aws.com":"i-09b9ec424040aa574"} node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] [] [{kops-controller Update v1 2022-05-11 02:32:36 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kops.k8s.io/instancegroup":{},"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/node":{}}}}} {kube-controller-manager Update v1 2022-05-11 02:32:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}},"f:spec":{"f:podCIDR":{},"f:podCIDRs":{".":{},"v:\"100.96.2.0/24\"":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"NetworkUnavailable\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}}}}} {kubelet Update v1 2022-05-11 02:33:32 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:csi.volume.kubernetes.io/nodeid":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:topology.ebs.csi.aws.com/zone":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"ExternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"ExternalIP\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:bootID":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}}]},Spec:NodeSpec{PodCIDR:100.96.2.0/24,DoNotUseExternalID:,ProviderID:aws:///us-west-2c/i-09b9ec424040aa574,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[100.96.2.0/24],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{133167038464 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3894337536 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{119850334420 0} {<nil>} 119850334420 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3789479936 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:NetworkUnavailable,Status:False,LastHeartbeatTime:2022-05-11 02:32:44 +0000 UTC,LastTransitionTime:2022-05-11 02:32:44 +0000 UTC,Reason:RouteCreated,Message:RouteController created a route,},NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-11 02:54:07 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status. AppArmor enabled,},},Addresses:[]NodeAddress{NodeAddress{Type:InternalIP,Address:172.20.119.106,},NodeAddress{Type:ExternalIP,Address:18.237.55.199,},NodeAddress{Type:Hostname,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:InternalDNS,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:ExternalDNS,Address:ec2-18-237-55-199.us-west-2.compute.amazonaws.com,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ec280ab512dfd6927c9759f5f208afa2,SystemUUID:ec280ab5-12df-d692-7c97-59f5f208afa2,BootID:965afe81-ea15-49ab-83a2-74e8d716b21b,KernelVersion:5.13.0-1021-aws,OSImage:Ubuntu 20.04.4 LTS,ContainerRuntimeVersion:containerd://1.4.6,KubeletVersion:v1.20.8,KubeProxyVersion:v1.20.8,OperatingSystem:linux,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[k8s.gcr.io/kube-proxy@sha256:0c867c82a0a8ce6d093595f9d2e4b10517d6c9c26323075de9d82d9f7d056bfc k8s.gcr.io/kube-proxy:v1.20.8],SizeBytes:52056682,},ContainerImage{Names:[607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver@sha256:7f611863431a70c8da183740f4cb36d5bf5be4e41cf53f27b864c95cd580b91e 607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver:17276],SizeBytes:24201197,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-provisioner@sha256:695505fcfcc69f1cf35665dce487aad447adbb9af69b796d6437f869015d1157 k8s.gcr.io/sig-storage/csi-provisioner:v2.1.1],SizeBytes:21212251,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-attacher@sha256:50c3cfd458fc8e0bf3c8c521eac39172009382fc66dc5044a330d137c6ed0b09 k8s.gcr.io/sig-storage/csi-attacher:v3.1.0],SizeBytes:20103959,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-resizer@sha256:7a5ba58a44e0d749e0767e4e37315bcf6a61f33ce3185c1991848af4db0fb70a k8s.gcr.io/sig-storage/csi-resizer:v1.1.0],SizeBytes:20096832,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-snapshotter@sha256:9af9bf28430b00a0cedeb2ec29acadce45e6afcecd8bdf31c793c624cfa75fa7 k8s.gcr.io/sig-storage/csi-snapshotter:v3.0.3],SizeBytes:19500777,},ContainerImage{Names:[k8s.gcr.io/sig-storage/snapshot-controller@sha256:00fcc441ea9f72899c25eed61d602272a2a58c5f0014332bdcb5ac24acef08e4 k8s.gcr.io/sig-storage/snapshot-controller:v4.0.0],SizeBytes:18952261,},ContainerImage{Names:[k8s.gcr.io/cpa/cluster-proportional-autoscaler@sha256:67640771ad9fc56f109d5b01e020f0c858e7c890bb0eb15ba0ebd325df3285e7 k8s.gcr.io/cpa/cluster-proportional-autoscaler:1.8.3],SizeBytes:15191740,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:a61d309da54641db41fb8f35718f744e9f730d4d0384f8c4b186ddc9f06cbd5f k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.1.0],SizeBytes:9068367,},ContainerImage{Names:[k8s.gcr.io/sig-storage/livenessprobe@sha256:529be2c9770add0cdd0c989115222ea9fc1be430c11095eb9f6dafcf98a36e2b k8s.gcr.io/sig-storage/livenessprobe:v2.4.0],SizeBytes:7960518,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:927d98197ec1141a368550822d18fa1c60bdae27b78b0c004f705f548c07814f k8s.gcr.io/pause:3.2],SizeBytes:299513,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},} ... skipping 107 lines ... [Testpattern: Dynamic PV (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould verify container cannot write to subpath readonly volumes [Slow] [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:427[0m [91mwhile waiting for volume init pod to succeed Unexpected error: <*errors.errorString | 0xc000eeec60>: { s: "Gave up after waiting 5m0s for pod \"volume-prep-provisioning-7117\" to be \"Succeeded or Failed\"", } Gave up after waiting 5m0s for pod "volume-prep-provisioning-7117" to be "Succeeded or Failed" occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:1021 [90m------------------------------[0m [36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m[36mS[0m [90m------------------------------[0m ... skipping 75 lines ... May 11 02:55:09.718: INFO: Creating resource for dynamic PV May 11 02:55:09.718: INFO: Using claimSize:1Gi, test suite supported size:{ 1Gi}, driver(ebs.csi.aws.com) supported size:{ 1Gi} [1mSTEP[0m: creating a StorageClass volume-expand-2256-e2e-scj4p2z [1mSTEP[0m: creating a claim [1mSTEP[0m: Expanding non-expandable pvc May 11 02:55:09.900: INFO: currentPvcSize {{1073741824 0} {<nil>} 1Gi BinarySI}, newSize {{2147483648 0} {<nil>} BinarySI} May 11 02:55:10.020: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:12.143: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:14.146: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:16.141: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:18.142: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:20.141: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:22.141: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:24.143: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:26.141: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:28.141: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:30.141: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:32.140: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:34.142: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:36.146: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:38.142: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:40.145: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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-2256-e2e-scj4p2z", ... // 2 identical fields } May 11 02:55:40.267: INFO: Error updating pvc ebs.csi.aws.comqnrpl: PersistentVolumeClaim "ebs.csi.aws.comqnrpl" 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 25 lines ... should not allow expansion of pvcs without AllowVolumeExpansion property [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volume_expand.go:157[0m [90m------------------------------[0m [36mS[0m[36mS[0m [90m------------------------------[0m [0mExternal Storage [Driver: ebs.csi.aws.com][0m [90m[Testpattern: Dynamic PV (default fs)] subPath[0m [1mshould fail if subpath directory is outside the volume [Slow][LinuxOnly][0m [37m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:240[0m [BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 [BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:185 [1mSTEP[0m: Creating a kubernetes client May 11 02:55:09.263: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-17276.k8s.local.kops.kubeconfig [1mSTEP[0m: Building a namespace api object, basename provisioning [1mSTEP[0m: 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/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:240 May 11 02:55:09.567: INFO: Creating resource for dynamic PV May 11 02:55:09.567: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass provisioning-4884-e2e-scw9kxd [1mSTEP[0m: creating a claim May 11 02:55:09.629: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: Creating pod pod-subpath-test-dynamicpv-vw77 [1mSTEP[0m: Checking for subpath error in container status May 11 03:00:10.001: INFO: Deleting pod "pod-subpath-test-dynamicpv-vw77" in namespace "provisioning-4884" May 11 03:00:10.064: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-vw77" to be fully deleted [1mSTEP[0m: Deleting pod May 11 03:00:14.192: INFO: Deleting pod "pod-subpath-test-dynamicpv-vw77" in namespace "provisioning-4884" [1mSTEP[0m: Deleting pvc May 11 03:00:14.375: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.comzm8gx" ... skipping 10 lines ... May 11 03:00:29.816: INFO: At 2022-05-11 02:55:09 +0000 UTC - event for ebs.csi.aws.comzm8gx: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 03:00:29.816: INFO: At 2022-05-11 02:55:09 +0000 UTC - event for ebs.csi.aws.comzm8gx: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 03:00:29.816: INFO: At 2022-05-11 02:55:09 +0000 UTC - event for ebs.csi.aws.comzm8gx: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "provisioning-4884/ebs.csi.aws.comzm8gx" May 11 03:00:29.816: INFO: At 2022-05-11 02:55:13 +0000 UTC - event for ebs.csi.aws.comzm8gx: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-f14b81d6-f2cd-4a4b-97e2-041374f03bf0 May 11 03:00:29.816: INFO: At 2022-05-11 02:55:13 +0000 UTC - event for pod-subpath-test-dynamicpv-vw77: {default-scheduler } Scheduled: Successfully assigned provisioning-4884/pod-subpath-test-dynamicpv-vw77 to ip-172-20-91-223.us-west-2.compute.internal May 11 03:00:29.816: INFO: At 2022-05-11 02:55:15 +0000 UTC - event for pod-subpath-test-dynamicpv-vw77: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-f14b81d6-f2cd-4a4b-97e2-041374f03bf0" May 11 03:00:29.816: INFO: At 2022-05-11 02:55:21 +0000 UTC - event for pod-subpath-test-dynamicpv-vw77: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-f14b81d6-f2cd-4a4b-97e2-041374f03bf0" : rpc error: code = Internal desc = could not format "/dev/nvme4n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-f14b81d6-f2cd-4a4b-97e2-041374f03bf0/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme4n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-f14b81d6-f2cd-4a4b-97e2-041374f03bf0/globalmount Output: May 11 03:00:29.816: INFO: At 2022-05-11 02:57:16 +0000 UTC - event for pod-subpath-test-dynamicpv-vw77: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[default-token-ff2dg test-volume liveness-probe-volume]: timed out waiting for the condition May 11 03:00:29.877: INFO: POD NODE PHASE GRACE CONDITIONS May 11 03:00:29.877: INFO: ... skipping 105 lines ... [91m[1m• Failure [322.706 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould fail if subpath directory is outside the volume [Slow][LinuxOnly] [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:240[0m [91mwhile waiting for subpath failure Unexpected error: <*errors.errorString | 0xc000b75050>: { s: "error waiting for pod subpath error to occur: timed out waiting for the condition", } error waiting for pod subpath error to occur: timed out waiting for the condition occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:718 [90m------------------------------[0m [36mS[0m [90m------------------------------[0m [0mExternal Storage [Driver: ebs.csi.aws.com][0m [90m[Testpattern: Dynamic PV (default fs)] subPath[0m [1mshould fail if subpath file is outside the volume [Slow][LinuxOnly][0m [37m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:256[0m [BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 [BeforeEach] [Testpattern: Dynamic PV (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:185 [1mSTEP[0m: Creating a kubernetes client May 11 02:55:40.575: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-17276.k8s.local.kops.kubeconfig [1mSTEP[0m: Building a namespace api object, basename provisioning [1mSTEP[0m: 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/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:256 May 11 02:55:40.872: INFO: Creating resource for dynamic PV May 11 02:55:40.872: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass provisioning-2406-e2e-scws527 [1mSTEP[0m: creating a claim May 11 02:55:40.933: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: Creating pod pod-subpath-test-dynamicpv-r4vd [1mSTEP[0m: Checking for subpath error in container status May 11 03:00:41.297: INFO: Deleting pod "pod-subpath-test-dynamicpv-r4vd" in namespace "provisioning-2406" May 11 03:00:41.360: INFO: Wait up to 5m0s for pod "pod-subpath-test-dynamicpv-r4vd" to be fully deleted [1mSTEP[0m: Deleting pod May 11 03:00:53.480: INFO: Deleting pod "pod-subpath-test-dynamicpv-r4vd" in namespace "provisioning-2406" [1mSTEP[0m: Deleting pvc May 11 03:00:53.658: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.commbcwf" ... skipping 10 lines ... May 11 03:01:09.088: INFO: At 2022-05-11 02:55:40 +0000 UTC - event for ebs.csi.aws.commbcwf: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 03:01:09.088: INFO: At 2022-05-11 02:55:41 +0000 UTC - event for ebs.csi.aws.commbcwf: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 03:01:09.088: INFO: At 2022-05-11 02:55:41 +0000 UTC - event for ebs.csi.aws.commbcwf: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "provisioning-2406/ebs.csi.aws.commbcwf" May 11 03:01:09.088: INFO: At 2022-05-11 02:55:44 +0000 UTC - event for ebs.csi.aws.commbcwf: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-dd35816e-44c7-4339-a223-9ba0f4f82f23 May 11 03:01:09.088: INFO: At 2022-05-11 02:55:45 +0000 UTC - event for pod-subpath-test-dynamicpv-r4vd: {default-scheduler } Scheduled: Successfully assigned provisioning-2406/pod-subpath-test-dynamicpv-r4vd to ip-172-20-91-223.us-west-2.compute.internal May 11 03:01:09.088: INFO: At 2022-05-11 02:55:47 +0000 UTC - event for pod-subpath-test-dynamicpv-r4vd: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-dd35816e-44c7-4339-a223-9ba0f4f82f23" May 11 03:01:09.088: INFO: At 2022-05-11 02:55:48 +0000 UTC - event for pod-subpath-test-dynamicpv-r4vd: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-dd35816e-44c7-4339-a223-9ba0f4f82f23" : rpc error: code = Internal desc = could not format "/dev/nvme2n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-dd35816e-44c7-4339-a223-9ba0f4f82f23/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme2n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-dd35816e-44c7-4339-a223-9ba0f4f82f23/globalmount Output: May 11 03:01:09.088: INFO: At 2022-05-11 02:57:48 +0000 UTC - event for pod-subpath-test-dynamicpv-r4vd: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[test-volume], unattached volumes=[test-volume liveness-probe-volume default-token-7v28d]: timed out waiting for the condition May 11 03:01:09.148: INFO: POD NODE PHASE GRACE CONDITIONS May 11 03:01:09.148: INFO: ... skipping 104 lines ... [91m[1m• Failure [330.588 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1mshould fail if subpath file is outside the volume [Slow][LinuxOnly] [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:256[0m [91mwhile waiting for subpath failure Unexpected error: <*errors.errorString | 0xc000837f40>: { s: "error waiting for pod subpath error to occur: timed out waiting for the condition", } error waiting for pod subpath error to occur: timed out waiting for the condition occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:718 [90m------------------------------[0m [BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] multiVolume [Slow] /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 ... skipping 35 lines ... [36m[1mS [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (ntfs)][Feature:Windows] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [36m[1mshould fail if subpath directory is outside the volume [Slow][LinuxOnly] [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:240[0m [36mDriver ebs.csi.aws.com doesn't support ntfs -- skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:121 [90m------------------------------[0m ... skipping 85 lines ... May 11 02:51:31.396: INFO: Creating resource for dynamic PV May 11 02:51:31.396: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass snapshotting-7762-e2e-scq964v [1mSTEP[0m: creating a claim May 11 02:51:31.462: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: [init] starting a pod to use the claim May 11 02:51:31.658: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-985hc" in namespace "snapshotting-7762" to be "Succeeded or Failed" May 11 02:51:31.723: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 64.307985ms May 11 02:51:33.788: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 2.129553089s May 11 02:51:35.854: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 4.195428065s May 11 02:51:37.920: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 6.261317803s May 11 02:51:39.986: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 8.327279905s May 11 02:51:42.050: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 10.392263648s ... skipping 425 lines ... May 11 03:06:21.327: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.668728165s May 11 03:06:23.389: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.730887344s May 11 03:06:25.451: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.793146686s May 11 03:06:27.512: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m55.854115328s May 11 03:06:29.573: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.915249683s May 11 03:06:31.636: INFO: Pod "pvc-snapshottable-tester-985hc": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.977733833s May 11 03:06:33.715: INFO: Error getting logs for pod pvc-snapshottable-tester-985hc: the server rejected our request for an unknown reason (get pods pvc-snapshottable-tester-985hc) May 11 03:06:33.715: INFO: Deleting pod "pvc-snapshottable-tester-985hc" in namespace "snapshotting-7762" May 11 03:06:33.777: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-985hc" to be fully deleted [AfterEach] volume snapshot controller /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:223 [1mSTEP[0m: Deleting pvc May 11 03:06:44.041: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.comq6dhx" ... skipping 11 lines ... May 11 03:07:04.546: INFO: At 2022-05-11 02:51:31 +0000 UTC - event for ebs.csi.aws.comq6dhx: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 03:07:04.546: INFO: At 2022-05-11 02:51:31 +0000 UTC - event for ebs.csi.aws.comq6dhx: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 03:07:04.546: INFO: At 2022-05-11 02:51:31 +0000 UTC - event for ebs.csi.aws.comq6dhx: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "snapshotting-7762/ebs.csi.aws.comq6dhx" May 11 03:07:04.546: INFO: At 2022-05-11 02:51:34 +0000 UTC - event for ebs.csi.aws.comq6dhx: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-58c80982-ca09-47b9-9ded-c320027284f6 May 11 03:07:04.546: INFO: At 2022-05-11 02:51:35 +0000 UTC - event for pvc-snapshottable-tester-985hc: {default-scheduler } Scheduled: Successfully assigned snapshotting-7762/pvc-snapshottable-tester-985hc to ip-172-20-91-223.us-west-2.compute.internal May 11 03:07:04.546: INFO: At 2022-05-11 02:51:37 +0000 UTC - event for pvc-snapshottable-tester-985hc: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-58c80982-ca09-47b9-9ded-c320027284f6" May 11 03:07:04.546: INFO: At 2022-05-11 02:51:39 +0000 UTC - event for pvc-snapshottable-tester-985hc: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-58c80982-ca09-47b9-9ded-c320027284f6" : rpc error: code = Internal desc = could not format "/dev/nvme1n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-58c80982-ca09-47b9-9ded-c320027284f6/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme1n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-58c80982-ca09-47b9-9ded-c320027284f6/globalmount Output: May 11 03:07:04.546: INFO: At 2022-05-11 02:53:38 +0000 UTC - event for pvc-snapshottable-tester-985hc: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[my-volume], unattached volumes=[my-volume default-token-jcmzr]: timed out waiting for the condition May 11 03:07:04.606: INFO: POD NODE PHASE GRACE CONDITIONS May 11 03:07:04.606: INFO: ... skipping 109 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:108[0m [91m[1m [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:227[0m should check snapshot fields, check restore correctly works after modifying source data, check deletion [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:245[0m [91mUnexpected error: <*errors.errorString | 0xc00093edc0>: { s: "Gave up after waiting 15m0s for pod \"pvc-snapshottable-tester-985hc\" to be \"Succeeded or Failed\"", } Gave up after waiting 15m0s for pod "pvc-snapshottable-tester-985hc" to be "Succeeded or Failed" occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/provisioning.go:675 [90m------------------------------[0m [36mS[0m [90m------------------------------[0m ... skipping 33 lines ... May 11 02:51:52.268: INFO: Creating resource for dynamic PV May 11 02:51:52.268: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass snapshotting-1789-e2e-scxzmxp [1mSTEP[0m: creating a claim May 11 02:51:52.335: INFO: Warning: Making PVC: VolumeMode specified as invalid empty string, treating as nil [1mSTEP[0m: [init] starting a pod to use the claim May 11 02:51:52.537: INFO: Waiting up to 15m0s for pod "pvc-snapshottable-tester-mw6n4" in namespace "snapshotting-1789" to be "Succeeded or Failed" May 11 02:51:52.603: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 65.933272ms May 11 02:51:54.671: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 2.134174688s May 11 02:51:56.739: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 4.201330338s May 11 02:51:58.805: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 6.267719234s May 11 02:52:00.871: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 8.334128316s May 11 02:52:02.941: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 10.403399301s ... skipping 424 lines ... May 11 03:06:41.000: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 14m48.463011607s May 11 03:06:43.064: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.526945858s May 11 03:06:45.129: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.591186344s May 11 03:06:47.194: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.656947867s May 11 03:06:49.259: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.721267925s May 11 03:06:51.322: INFO: Pod "pvc-snapshottable-tester-mw6n4": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.785148406s May 11 03:06:53.394: INFO: Error getting logs for pod pvc-snapshottable-tester-mw6n4: the server rejected our request for an unknown reason (get pods pvc-snapshottable-tester-mw6n4) May 11 03:06:53.394: INFO: Deleting pod "pvc-snapshottable-tester-mw6n4" in namespace "snapshotting-1789" May 11 03:06:53.459: INFO: Wait up to 5m0s for pod "pvc-snapshottable-tester-mw6n4" to be fully deleted [AfterEach] volume snapshot controller /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:223 [1mSTEP[0m: Deleting pvc May 11 03:07:03.720: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.com2k5pn" ... skipping 10 lines ... May 11 03:07:19.179: INFO: At 2022-05-11 02:51:52 +0000 UTC - event for ebs.csi.aws.com2k5pn: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 03:07:19.179: INFO: At 2022-05-11 02:51:52 +0000 UTC - event for ebs.csi.aws.com2k5pn: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 03:07:19.179: INFO: At 2022-05-11 02:51:52 +0000 UTC - event for ebs.csi.aws.com2k5pn: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "snapshotting-1789/ebs.csi.aws.com2k5pn" May 11 03:07:19.179: INFO: At 2022-05-11 02:51:55 +0000 UTC - event for ebs.csi.aws.com2k5pn: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-2fe96b27-efc7-4a29-a282-2ed8eb1bb052 May 11 03:07:19.179: INFO: At 2022-05-11 02:51:56 +0000 UTC - event for pvc-snapshottable-tester-mw6n4: {default-scheduler } Scheduled: Successfully assigned snapshotting-1789/pvc-snapshottable-tester-mw6n4 to ip-172-20-91-223.us-west-2.compute.internal May 11 03:07:19.179: INFO: At 2022-05-11 02:51:58 +0000 UTC - event for pvc-snapshottable-tester-mw6n4: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-2fe96b27-efc7-4a29-a282-2ed8eb1bb052" May 11 03:07:19.179: INFO: At 2022-05-11 02:52:00 +0000 UTC - event for pvc-snapshottable-tester-mw6n4: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-2fe96b27-efc7-4a29-a282-2ed8eb1bb052" : rpc error: code = Internal desc = could not format "/dev/nvme3n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-2fe96b27-efc7-4a29-a282-2ed8eb1bb052/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme3n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-2fe96b27-efc7-4a29-a282-2ed8eb1bb052/globalmount Output: May 11 03:07:19.179: INFO: At 2022-05-11 02:53:59 +0000 UTC - event for pvc-snapshottable-tester-mw6n4: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[my-volume], unattached volumes=[default-token-dfqvg my-volume]: timed out waiting for the condition May 11 03:07:19.179: INFO: At 2022-05-11 02:56:17 +0000 UTC - event for pvc-snapshottable-tester-mw6n4: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[my-volume], unattached volumes=[my-volume default-token-dfqvg]: timed out waiting for the condition May 11 03:07:19.241: INFO: POD NODE PHASE GRACE CONDITIONS ... skipping 113 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:108[0m [91m[1m [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:227[0m should check snapshot fields, check restore correctly works after modifying source data, check deletion [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/snapshottable.go:245[0m [91mUnexpected error: <*errors.errorString | 0xc0010c0b60>: { s: "Gave up after waiting 15m0s for pod \"pvc-snapshottable-tester-mw6n4\" to be \"Succeeded or Failed\"", } Gave up after waiting 15m0s for pod "pvc-snapshottable-tester-mw6n4" to be "Succeeded or Failed" occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/provisioning.go:675 [90m------------------------------[0m [36mS[0m [90m------------------------------[0m ... skipping 88 lines ... May 11 03:10:36.859: INFO: At 2022-05-11 03:00:32 +0000 UTC - event for ebs.csi.aws.comcv4wc: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 03:10:36.860: INFO: At 2022-05-11 03:00:32 +0000 UTC - event for ebs.csi.aws.comcv4wc: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 03:10:36.860: INFO: At 2022-05-11 03:00:32 +0000 UTC - event for ebs.csi.aws.comcv4wc: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "fsgroupchangepolicy-8990/ebs.csi.aws.comcv4wc" May 11 03:10:36.860: INFO: At 2022-05-11 03:00:35 +0000 UTC - event for ebs.csi.aws.comcv4wc: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-d2af134e-a3c4-4cfc-b38f-a561e8a55f5b May 11 03:10:36.860: INFO: At 2022-05-11 03:00:36 +0000 UTC - event for pod-edb827ca-9461-4231-b7a6-3c248bdc51cf: {default-scheduler } Scheduled: Successfully assigned fsgroupchangepolicy-8990/pod-edb827ca-9461-4231-b7a6-3c248bdc51cf to ip-172-20-91-223.us-west-2.compute.internal May 11 03:10:36.860: INFO: At 2022-05-11 03:00:38 +0000 UTC - event for pod-edb827ca-9461-4231-b7a6-3c248bdc51cf: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-d2af134e-a3c4-4cfc-b38f-a561e8a55f5b" May 11 03:10:36.860: INFO: At 2022-05-11 03:00:40 +0000 UTC - event for pod-edb827ca-9461-4231-b7a6-3c248bdc51cf: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-d2af134e-a3c4-4cfc-b38f-a561e8a55f5b" : rpc error: code = Internal desc = could not format "/dev/nvme4n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-d2af134e-a3c4-4cfc-b38f-a561e8a55f5b/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme4n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-d2af134e-a3c4-4cfc-b38f-a561e8a55f5b/globalmount Output: May 11 03:10:36.860: INFO: At 2022-05-11 03:02:39 +0000 UTC - event for pod-edb827ca-9461-4231-b7a6-3c248bdc51cf: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-dqnlx]: timed out waiting for the condition May 11 03:10:36.860: INFO: At 2022-05-11 03:07:25 +0000 UTC - event for pod-edb827ca-9461-4231-b7a6-3c248bdc51cf: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-dqnlx]: error processing PVC fsgroupchangepolicy-8990/ebs.csi.aws.comcv4wc: PVC is being deleted May 11 03:10:36.860: INFO: At 2022-05-11 03:07:36 +0000 UTC - event for pod-edb827ca-9461-4231-b7a6-3c248bdc51cf: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-dqnlx volume1]: error processing PVC fsgroupchangepolicy-8990/ebs.csi.aws.comcv4wc: PVC is being deleted May 11 03:10:36.921: INFO: POD NODE PHASE GRACE CONDITIONS May 11 03:10:36.921: INFO: pod-edb827ca-9461-4231-b7a6-3c248bdc51cf ip-172-20-91-223.us-west-2.compute.internal Pending [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:00:36 +0000 UTC } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:00:36 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:00:36 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:00:36 +0000 UTC }] May 11 03:10:36.921: INFO: May 11 03:10:36.983: INFO: Logging node info for node ip-172-20-119-106.us-west-2.compute.internal May 11 03:10:37.045: INFO: Node Info: &Node{ObjectMeta:{ip-172-20-119-106.us-west-2.compute.internal ff301b1b-3126-4316-af7e-3195f1ee7c08 8783 0 2022-05-11 02:32:36 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:c5.large beta.kubernetes.io/os:linux failure-domain.beta.kubernetes.io/region:us-west-2 failure-domain.beta.kubernetes.io/zone:us-west-2c kops.k8s.io/instancegroup:nodes-us-west-2c kubernetes.io/arch:amd64 kubernetes.io/hostname:ip-172-20-119-106.us-west-2.compute.internal kubernetes.io/os:linux kubernetes.io/role:node node-role.kubernetes.io/node: node.kubernetes.io/instance-type:c5.large topology.ebs.csi.aws.com/zone:us-west-2c topology.kubernetes.io/region:us-west-2 topology.kubernetes.io/zone:us-west-2c] map[csi.volume.kubernetes.io/nodeid:{"ebs.csi.aws.com":"i-09b9ec424040aa574"} node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] [] [{kops-controller Update v1 2022-05-11 02:32:36 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kops.k8s.io/instancegroup":{},"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/node":{}}}}} {kube-controller-manager Update v1 2022-05-11 02:32:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}},"f:spec":{"f:podCIDR":{},"f:podCIDRs":{".":{},"v:\"100.96.2.0/24\"":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"NetworkUnavailable\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}}}}} {kubelet Update v1 2022-05-11 02:33:32 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:csi.volume.kubernetes.io/nodeid":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:topology.ebs.csi.aws.com/zone":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"ExternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"ExternalIP\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:bootID":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}}]},Spec:NodeSpec{PodCIDR:100.96.2.0/24,DoNotUseExternalID:,ProviderID:aws:///us-west-2c/i-09b9ec424040aa574,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[100.96.2.0/24],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{133167038464 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3894337536 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{119850334420 0} {<nil>} 119850334420 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3789479936 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:NetworkUnavailable,Status:False,LastHeartbeatTime:2022-05-11 02:32:44 +0000 UTC,LastTransitionTime:2022-05-11 02:32:44 +0000 UTC,Reason:RouteCreated,Message:RouteController created a route,},NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status. AppArmor enabled,},},Addresses:[]NodeAddress{NodeAddress{Type:InternalIP,Address:172.20.119.106,},NodeAddress{Type:ExternalIP,Address:18.237.55.199,},NodeAddress{Type:Hostname,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:InternalDNS,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:ExternalDNS,Address:ec2-18-237-55-199.us-west-2.compute.amazonaws.com,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ec280ab512dfd6927c9759f5f208afa2,SystemUUID:ec280ab5-12df-d692-7c97-59f5f208afa2,BootID:965afe81-ea15-49ab-83a2-74e8d716b21b,KernelVersion:5.13.0-1021-aws,OSImage:Ubuntu 20.04.4 LTS,ContainerRuntimeVersion:containerd://1.4.6,KubeletVersion:v1.20.8,KubeProxyVersion:v1.20.8,OperatingSystem:linux,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[k8s.gcr.io/kube-proxy@sha256:0c867c82a0a8ce6d093595f9d2e4b10517d6c9c26323075de9d82d9f7d056bfc k8s.gcr.io/kube-proxy:v1.20.8],SizeBytes:52056682,},ContainerImage{Names:[607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver@sha256:7f611863431a70c8da183740f4cb36d5bf5be4e41cf53f27b864c95cd580b91e 607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver:17276],SizeBytes:24201197,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-provisioner@sha256:695505fcfcc69f1cf35665dce487aad447adbb9af69b796d6437f869015d1157 k8s.gcr.io/sig-storage/csi-provisioner:v2.1.1],SizeBytes:21212251,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-attacher@sha256:50c3cfd458fc8e0bf3c8c521eac39172009382fc66dc5044a330d137c6ed0b09 k8s.gcr.io/sig-storage/csi-attacher:v3.1.0],SizeBytes:20103959,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-resizer@sha256:7a5ba58a44e0d749e0767e4e37315bcf6a61f33ce3185c1991848af4db0fb70a k8s.gcr.io/sig-storage/csi-resizer:v1.1.0],SizeBytes:20096832,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-snapshotter@sha256:9af9bf28430b00a0cedeb2ec29acadce45e6afcecd8bdf31c793c624cfa75fa7 k8s.gcr.io/sig-storage/csi-snapshotter:v3.0.3],SizeBytes:19500777,},ContainerImage{Names:[k8s.gcr.io/sig-storage/snapshot-controller@sha256:00fcc441ea9f72899c25eed61d602272a2a58c5f0014332bdcb5ac24acef08e4 k8s.gcr.io/sig-storage/snapshot-controller:v4.0.0],SizeBytes:18952261,},ContainerImage{Names:[k8s.gcr.io/cpa/cluster-proportional-autoscaler@sha256:67640771ad9fc56f109d5b01e020f0c858e7c890bb0eb15ba0ebd325df3285e7 k8s.gcr.io/cpa/cluster-proportional-autoscaler:1.8.3],SizeBytes:15191740,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:a61d309da54641db41fb8f35718f744e9f730d4d0384f8c4b186ddc9f06cbd5f k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.1.0],SizeBytes:9068367,},ContainerImage{Names:[k8s.gcr.io/sig-storage/livenessprobe@sha256:529be2c9770add0cdd0c989115222ea9fc1be430c11095eb9f6dafcf98a36e2b k8s.gcr.io/sig-storage/livenessprobe:v2.4.0],SizeBytes:7960518,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:927d98197ec1141a368550822d18fa1c60bdae27b78b0c004f705f548c07814f k8s.gcr.io/pause:3.2],SizeBytes:299513,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},} ... skipping 108 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1m(Always)[LinuxOnly], pod created with an initial fsgroup, new pod fsgroup applied to volume contents [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208[0m [91mUnexpected error: <*errors.errorString | 0xc0011a8ce0>: { s: "pod \"pod-edb827ca-9461-4231-b7a6-3c248bdc51cf\" is not Running: timed out waiting for the condition", } pod "pod-edb827ca-9461-4231-b7a6-3c248bdc51cf" is not Running: timed out waiting for the condition occurred[0m ... skipping 343 lines ... May 11 03:11:17.130: INFO: At 2022-05-11 03:01:12 +0000 UTC - event for ebs.csi.aws.combcpsf: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding May 11 03:11:17.131: INFO: At 2022-05-11 03:01:12 +0000 UTC - event for ebs.csi.aws.combcpsf: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "ebs.csi.aws.com" or manually created by system administrator May 11 03:11:17.131: INFO: At 2022-05-11 03:01:12 +0000 UTC - event for ebs.csi.aws.combcpsf: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } Provisioning: External provisioner is provisioning volume for claim "fsgroupchangepolicy-4607/ebs.csi.aws.combcpsf" May 11 03:11:17.131: INFO: At 2022-05-11 03:01:15 +0000 UTC - event for ebs.csi.aws.combcpsf: {ebs.csi.aws.com_ebs-csi-controller-59f785c768-fgv7b_ef2ebebc-eb8a-4b99-9666-7a37d89f6b84 } ProvisioningSucceeded: Successfully provisioned volume pvc-1d552029-0de6-4a6c-8531-9582274dd392 May 11 03:11:17.131: INFO: At 2022-05-11 03:01:16 +0000 UTC - event for pod-041770ef-27cb-4dae-99bb-73c8fabf712f: {default-scheduler } Scheduled: Successfully assigned fsgroupchangepolicy-4607/pod-041770ef-27cb-4dae-99bb-73c8fabf712f to ip-172-20-91-223.us-west-2.compute.internal May 11 03:11:17.131: INFO: At 2022-05-11 03:01:18 +0000 UTC - event for pod-041770ef-27cb-4dae-99bb-73c8fabf712f: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-1d552029-0de6-4a6c-8531-9582274dd392" May 11 03:11:17.131: INFO: At 2022-05-11 03:01:20 +0000 UTC - event for pod-041770ef-27cb-4dae-99bb-73c8fabf712f: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: MountVolume.MountDevice failed for volume "pvc-1d552029-0de6-4a6c-8531-9582274dd392" : rpc error: code = Internal desc = could not format "/dev/nvme2n1" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-1d552029-0de6-4a6c-8531-9582274dd392/globalmount": mount failed: exec: "mount": executable file not found in $PATH Mounting command: mount Mounting arguments: -t ext4 -o defaults /dev/nvme2n1 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-1d552029-0de6-4a6c-8531-9582274dd392/globalmount Output: May 11 03:11:17.131: INFO: At 2022-05-11 03:03:19 +0000 UTC - event for pod-041770ef-27cb-4dae-99bb-73c8fabf712f: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[default-token-6sz98 volume1]: timed out waiting for the condition May 11 03:11:17.131: INFO: At 2022-05-11 03:05:34 +0000 UTC - event for pod-041770ef-27cb-4dae-99bb-73c8fabf712f: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-6sz98]: timed out waiting for the condition May 11 03:11:17.131: INFO: At 2022-05-11 03:08:06 +0000 UTC - event for pod-041770ef-27cb-4dae-99bb-73c8fabf712f: {kubelet ip-172-20-91-223.us-west-2.compute.internal} FailedMount: Unable to attach or mount volumes: unmounted volumes=[volume1], unattached volumes=[volume1 default-token-6sz98]: error processing PVC fsgroupchangepolicy-4607/ebs.csi.aws.combcpsf: PVC is being deleted May 11 03:11:17.193: INFO: POD NODE PHASE GRACE CONDITIONS May 11 03:11:17.193: INFO: pod-041770ef-27cb-4dae-99bb-73c8fabf712f ip-172-20-91-223.us-west-2.compute.internal Pending [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:01:16 +0000 UTC } {Ready False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:01:16 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:01:16 +0000 UTC ContainersNotReady containers with unready status: [write-pod]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2022-05-11 03:01:16 +0000 UTC }] May 11 03:11:17.194: INFO: May 11 03:11:17.258: INFO: Logging node info for node ip-172-20-119-106.us-west-2.compute.internal May 11 03:11:17.321: INFO: Node Info: &Node{ObjectMeta:{ip-172-20-119-106.us-west-2.compute.internal ff301b1b-3126-4316-af7e-3195f1ee7c08 8783 0 2022-05-11 02:32:36 +0000 UTC <nil> <nil> map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/instance-type:c5.large beta.kubernetes.io/os:linux failure-domain.beta.kubernetes.io/region:us-west-2 failure-domain.beta.kubernetes.io/zone:us-west-2c kops.k8s.io/instancegroup:nodes-us-west-2c kubernetes.io/arch:amd64 kubernetes.io/hostname:ip-172-20-119-106.us-west-2.compute.internal kubernetes.io/os:linux kubernetes.io/role:node node-role.kubernetes.io/node: node.kubernetes.io/instance-type:c5.large topology.ebs.csi.aws.com/zone:us-west-2c topology.kubernetes.io/region:us-west-2 topology.kubernetes.io/zone:us-west-2c] map[csi.volume.kubernetes.io/nodeid:{"ebs.csi.aws.com":"i-09b9ec424040aa574"} node.alpha.kubernetes.io/ttl:0 volumes.kubernetes.io/controller-managed-attach-detach:true] [] [] [{kops-controller Update v1 2022-05-11 02:32:36 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{"f:kops.k8s.io/instancegroup":{},"f:kubernetes.io/role":{},"f:node-role.kubernetes.io/node":{}}}}} {kube-controller-manager Update v1 2022-05-11 02:32:44 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{"f:node.alpha.kubernetes.io/ttl":{}}},"f:spec":{"f:podCIDR":{},"f:podCIDRs":{".":{},"v:\"100.96.2.0/24\"":{}}},"f:status":{"f:conditions":{"k:{\"type\":\"NetworkUnavailable\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}}}}} {kubelet Update v1 2022-05-11 02:33:32 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:csi.volume.kubernetes.io/nodeid":{},"f:volumes.kubernetes.io/controller-managed-attach-detach":{}},"f:labels":{".":{},"f:beta.kubernetes.io/arch":{},"f:beta.kubernetes.io/instance-type":{},"f:beta.kubernetes.io/os":{},"f:failure-domain.beta.kubernetes.io/region":{},"f:failure-domain.beta.kubernetes.io/zone":{},"f:kubernetes.io/arch":{},"f:kubernetes.io/hostname":{},"f:kubernetes.io/os":{},"f:node.kubernetes.io/instance-type":{},"f:topology.ebs.csi.aws.com/zone":{},"f:topology.kubernetes.io/region":{},"f:topology.kubernetes.io/zone":{}}},"f:spec":{"f:providerID":{}},"f:status":{"f:addresses":{".":{},"k:{\"type\":\"ExternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"ExternalIP\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"Hostname\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalDNS\"}":{".":{},"f:address":{},"f:type":{}},"k:{\"type\":\"InternalIP\"}":{".":{},"f:address":{},"f:type":{}}},"f:allocatable":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:capacity":{".":{},"f:attachable-volumes-aws-ebs":{},"f:cpu":{},"f:ephemeral-storage":{},"f:hugepages-1Gi":{},"f:hugepages-2Mi":{},"f:memory":{},"f:pods":{}},"f:conditions":{".":{},"k:{\"type\":\"DiskPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"MemoryPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"PIDPressure\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}},"k:{\"type\":\"Ready\"}":{".":{},"f:lastHeartbeatTime":{},"f:lastTransitionTime":{},"f:message":{},"f:reason":{},"f:status":{},"f:type":{}}},"f:daemonEndpoints":{"f:kubeletEndpoint":{"f:Port":{}}},"f:images":{},"f:nodeInfo":{"f:architecture":{},"f:bootID":{},"f:containerRuntimeVersion":{},"f:kernelVersion":{},"f:kubeProxyVersion":{},"f:kubeletVersion":{},"f:machineID":{},"f:operatingSystem":{},"f:osImage":{},"f:systemUUID":{}}}}}]},Spec:NodeSpec{PodCIDR:100.96.2.0/24,DoNotUseExternalID:,ProviderID:aws:///us-west-2c/i-09b9ec424040aa574,Unschedulable:false,Taints:[]Taint{},ConfigSource:nil,PodCIDRs:[100.96.2.0/24],},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{133167038464 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3894337536 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-aws-ebs: {{25 0} {<nil>} 25 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{119850334420 0} {<nil>} 119850334420 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3789479936 0} {<nil>} BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[]NodeCondition{NodeCondition{Type:NetworkUnavailable,Status:False,LastHeartbeatTime:2022-05-11 02:32:44 +0000 UTC,LastTransitionTime:2022-05-11 02:32:44 +0000 UTC,Reason:RouteCreated,Message:RouteController created a route,},NodeCondition{Type:MemoryPressure,Status:False,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientMemory,Message:kubelet has sufficient memory available,},NodeCondition{Type:DiskPressure,Status:False,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasNoDiskPressure,Message:kubelet has no disk pressure,},NodeCondition{Type:PIDPressure,Status:False,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletHasSufficientPID,Message:kubelet has sufficient PID available,},NodeCondition{Type:Ready,Status:True,LastHeartbeatTime:2022-05-11 03:09:11 +0000 UTC,LastTransitionTime:2022-05-11 02:32:36 +0000 UTC,Reason:KubeletReady,Message:kubelet is posting ready status. AppArmor enabled,},},Addresses:[]NodeAddress{NodeAddress{Type:InternalIP,Address:172.20.119.106,},NodeAddress{Type:ExternalIP,Address:18.237.55.199,},NodeAddress{Type:Hostname,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:InternalDNS,Address:ip-172-20-119-106.us-west-2.compute.internal,},NodeAddress{Type:ExternalDNS,Address:ec2-18-237-55-199.us-west-2.compute.amazonaws.com,},},DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ec280ab512dfd6927c9759f5f208afa2,SystemUUID:ec280ab5-12df-d692-7c97-59f5f208afa2,BootID:965afe81-ea15-49ab-83a2-74e8d716b21b,KernelVersion:5.13.0-1021-aws,OSImage:Ubuntu 20.04.4 LTS,ContainerRuntimeVersion:containerd://1.4.6,KubeletVersion:v1.20.8,KubeProxyVersion:v1.20.8,OperatingSystem:linux,Architecture:amd64,},Images:[]ContainerImage{ContainerImage{Names:[k8s.gcr.io/kube-proxy@sha256:0c867c82a0a8ce6d093595f9d2e4b10517d6c9c26323075de9d82d9f7d056bfc k8s.gcr.io/kube-proxy:v1.20.8],SizeBytes:52056682,},ContainerImage{Names:[607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver@sha256:7f611863431a70c8da183740f4cb36d5bf5be4e41cf53f27b864c95cd580b91e 607362164682.dkr.ecr.us-west-2.amazonaws.com/aws-ebs-csi-driver:17276],SizeBytes:24201197,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-provisioner@sha256:695505fcfcc69f1cf35665dce487aad447adbb9af69b796d6437f869015d1157 k8s.gcr.io/sig-storage/csi-provisioner:v2.1.1],SizeBytes:21212251,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-attacher@sha256:50c3cfd458fc8e0bf3c8c521eac39172009382fc66dc5044a330d137c6ed0b09 k8s.gcr.io/sig-storage/csi-attacher:v3.1.0],SizeBytes:20103959,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-resizer@sha256:7a5ba58a44e0d749e0767e4e37315bcf6a61f33ce3185c1991848af4db0fb70a k8s.gcr.io/sig-storage/csi-resizer:v1.1.0],SizeBytes:20096832,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-snapshotter@sha256:9af9bf28430b00a0cedeb2ec29acadce45e6afcecd8bdf31c793c624cfa75fa7 k8s.gcr.io/sig-storage/csi-snapshotter:v3.0.3],SizeBytes:19500777,},ContainerImage{Names:[k8s.gcr.io/sig-storage/snapshot-controller@sha256:00fcc441ea9f72899c25eed61d602272a2a58c5f0014332bdcb5ac24acef08e4 k8s.gcr.io/sig-storage/snapshot-controller:v4.0.0],SizeBytes:18952261,},ContainerImage{Names:[k8s.gcr.io/cpa/cluster-proportional-autoscaler@sha256:67640771ad9fc56f109d5b01e020f0c858e7c890bb0eb15ba0ebd325df3285e7 k8s.gcr.io/cpa/cluster-proportional-autoscaler:1.8.3],SizeBytes:15191740,},ContainerImage{Names:[k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:a61d309da54641db41fb8f35718f744e9f730d4d0384f8c4b186ddc9f06cbd5f k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.1.0],SizeBytes:9068367,},ContainerImage{Names:[k8s.gcr.io/sig-storage/livenessprobe@sha256:529be2c9770add0cdd0c989115222ea9fc1be430c11095eb9f6dafcf98a36e2b k8s.gcr.io/sig-storage/livenessprobe:v2.4.0],SizeBytes:7960518,},ContainerImage{Names:[k8s.gcr.io/pause@sha256:927d98197ec1141a368550822d18fa1c60bdae27b78b0c004f705f548c07814f k8s.gcr.io/pause:3.2],SizeBytes:299513,},},VolumesInUse:[],VolumesAttached:[]AttachedVolume{},Config:nil,},} ... skipping 108 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (default fs)] fsgroupchangepolicy [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [91m[1m(Always)[LinuxOnly], pod created with an initial fsgroup, volume contents ownership changed in first pod, new pod with same fsgroup applied to the volume contents [It][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:208[0m [91mUnexpected error: <*errors.errorString | 0xc001388900>: { s: "pod \"pod-041770ef-27cb-4dae-99bb-73c8fabf712f\" is not Running: timed out waiting for the condition", } pod "pod-041770ef-27cb-4dae-99bb-73c8fabf712f" is not Running: timed out waiting for the condition occurred[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/fsgroupchangepolicy.go:250 [90m------------------------------[0m [0mExternal Storage [Driver: ebs.csi.aws.com][0m [90m[Testpattern: Dynamic PV (filesystem volmode)] volumeMode[0m [1mshould fail to use a volume in a pod with mismatched mode [Slow][0m [37m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297[0m [BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 [BeforeEach] [Testpattern: Dynamic PV (filesystem volmode)] volumeMode /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:185 [1mSTEP[0m: Creating a kubernetes client May 11 03:11:19.321: INFO: >>> kubeConfig: /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/hack/e2e/csi-test-artifacts/test-cluster-17276.k8s.local.kops.kubeconfig [1mSTEP[0m: Building a namespace api object, basename volumemode [1mSTEP[0m: 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/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297 May 11 03:11:19.634: INFO: Creating resource for dynamic PV May 11 03:11:19.634: INFO: Using claimSize:1Gi, test suite supported size:{ 1Mi}, driver(ebs.csi.aws.com) supported size:{ 1Mi} [1mSTEP[0m: creating a StorageClass volumemode-4695-e2e-scdn8vl [1mSTEP[0m: creating a claim [1mSTEP[0m: Creating pod [1mSTEP[0m: Waiting for the pod to fail May 11 03:11:26.081: INFO: Deleting pod "pod-03edba0a-2d95-4b65-ae93-d10925486c6d" in namespace "volumemode-4695" May 11 03:11:26.145: INFO: Wait up to 5m0s for pod "pod-03edba0a-2d95-4b65-ae93-d10925486c6d" to be fully deleted [1mSTEP[0m: Deleting pvc May 11 03:11:34.400: INFO: Deleting PersistentVolumeClaim "ebs.csi.aws.comvtr9w" May 11 03:11:34.464: INFO: Waiting up to 5m0s for PersistentVolume pvc-ef1d6d9c-f5c4-4ae1-aafe-155aecf11f8d to get deleted May 11 03:11:34.529: INFO: PersistentVolume pvc-ef1d6d9c-f5c4-4ae1-aafe-155aecf11f8d found and phase=Released (64.37404ms) ... skipping 7 lines ... [32m• [SLOW TEST:20.472 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Dynamic PV (filesystem volmode)] volumeMode [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m should fail to use a volume in a pod with mismatched mode [Slow] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:297[0m [90m------------------------------[0m [36mS[0m[36mS[0m [90m------------------------------[0m [BeforeEach] [Testpattern: Inline-volume (default fs)] subPath /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:51 ... skipping 4 lines ... [36m[1mS [SKIPPING] in Spec Setup (BeforeEach) [0.001 seconds][0m External Storage [Driver: ebs.csi.aws.com] [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:175[0m [Testpattern: Inline-volume (default fs)] subPath [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/framework/testsuite.go:50[0m [36m[1mshould fail if non-existent subpath is outside the volume [Slow][LinuxOnly] [BeforeEach][0m [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:267[0m [36mDriver "ebs.csi.aws.com" does not support volume type "InlineVolume" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m ... skipping 63 lines ... [90m/home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:427[0m [36mDriver "ebs.csi.aws.com" does not support volume type "InlineVolume" - skipping[0m /home/prow/go/src/github.com/kubernetes-sigs/aws-ebs-csi-driver/vendor/k8s.io/kubernetes/test/e2e/storage/external/external.go:263 [90m------------------------------[0m {"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:169","func":"k8s.io/test-infra/prow/entrypoint.Options.ExecuteProcess","level":"error","msg":"Entrypoint received interrupt: terminated","severity":"error","time":"2022-05-11T03:11:59Z"} ++ early_exit_handler ++ '[' -n 177 ']' ++ kill -TERM 177 ++ cleanup_dind ++ [[ true == \t\r\u\e ]] ++ echo 'Cleaning up after docker' ... skipping 2 lines ...