Cilium #14287: SchedulerPredicates Kubernetes conformance test failure

gistfile1.txt

[sig-scheduling] SchedulerPredicates [Serial] 
  validates that there is no conflict between pods with same hostPort but different hostIP and protocol [Conformance]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:629
[BeforeEach] [sig-scheduling] SchedulerPredicates [Serial]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:174
STEP: Creating a kubernetes client
Dec  4 18:49:31.021: INFO: >>> kubeConfig: /tmp/kubeconfig-941584854
STEP: Building a namespace api object, basename sched-pred
STEP: Waiting for a default service account to be provisioned in namespace
[BeforeEach] [sig-scheduling] SchedulerPredicates [Serial]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/scheduling/predicates.go:92
Dec  4 18:49:31.071: INFO: Waiting up to 1m0s for all (but 0) nodes to be ready
Dec  4 18:49:31.079: INFO: Waiting for terminating namespaces to be deleted...
Dec  4 18:49:31.082: INFO: 
Logging pods the apiserver thinks is on node ip-10-0-14-203 before test
Dec  4 18:49:31.086: INFO: cilium-agent-4jzqz from kube-system started at 2020-12-04 18:28:01 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.086: INFO: 	Container cilium-agent ready: true, restart count 0
Dec  4 18:49:31.087: INFO: kube-proxy-6kbd9 from kube-system started at 2020-12-04 18:28:01 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.087: INFO: 	Container kube-proxy ready: true, restart count 0
Dec  4 18:49:31.087: INFO: sonobuoy from sonobuoy started at 2020-12-04 18:29:41 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.087: INFO: 	Container kube-sonobuoy ready: true, restart count 0
Dec  4 18:49:31.087: INFO: sonobuoy-e2e-job-8e0ff392406745f9 from sonobuoy started at 2020-12-04 18:29:45 +0000 UTC (2 container statuses recorded)
Dec  4 18:49:31.087: INFO: 	Container e2e ready: true, restart count 0
Dec  4 18:49:31.087: INFO: 	Container sonobuoy-worker ready: true, restart count 0
Dec  4 18:49:31.087: INFO: sonobuoy-systemd-logs-daemon-set-24a6dce7c2d744cc-drskn from sonobuoy started at 2020-12-04 18:29:46 +0000 UTC (2 container statuses recorded)
Dec  4 18:49:31.087: INFO: 	Container sonobuoy-worker ready: true, restart count 0
Dec  4 18:49:31.087: INFO: 	Container systemd-logs ready: true, restart count 0
Dec  4 18:49:31.087: INFO: 
Logging pods the apiserver thinks is on node ip-10-0-29-34 before test
Dec  4 18:49:31.091: INFO: cilium-agent-lt5kc from kube-system started at 2020-12-04 18:27:44 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.091: INFO: 	Container cilium-agent ready: true, restart count 0
Dec  4 18:49:31.091: INFO: cilium-operator-57f74bb787-v7pdz from kube-system started at 2020-12-04 18:27:44 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.091: INFO: 	Container cilium-operator ready: true, restart count 0
Dec  4 18:49:31.091: INFO: coredns-7d8995c4cd-jxtgr from kube-system started at 2020-12-04 18:28:12 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.091: INFO: 	Container coredns ready: true, restart count 0
Dec  4 18:49:31.092: INFO: coredns-7d8995c4cd-td7mt from kube-system started at 2020-12-04 18:28:06 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.092: INFO: 	Container coredns ready: true, restart count 0
Dec  4 18:49:31.092: INFO: kube-proxy-nssqr from kube-system started at 2020-12-04 18:27:44 +0000 UTC (1 container statuses recorded)
Dec  4 18:49:31.092: INFO: 	Container kube-proxy ready: true, restart count 0
Dec  4 18:49:31.092: INFO: sonobuoy-systemd-logs-daemon-set-24a6dce7c2d744cc-mqgz8 from sonobuoy started at 2020-12-04 18:29:46 +0000 UTC (2 container statuses recorded)
Dec  4 18:49:31.092: INFO: 	Container sonobuoy-worker ready: true, restart count 0
Dec  4 18:49:31.092: INFO: 	Container systemd-logs ready: true, restart count 0
[It] validates that there is no conflict between pods with same hostPort but different hostIP and protocol [Conformance]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:629
STEP: Trying to launch a pod without a label to get a node which can launch it.
STEP: Explicitly delete pod here to free the resource it takes.
STEP: Trying to apply a random label on the found node.
STEP: verifying the node has the label kubernetes.io/e2e-2dab2a44-5b13-4d39-9f68-c9bf55a898fe 90
STEP: Trying to create a pod(pod1) with hostport 54321 and hostIP 127.0.0.1 and expect scheduled
STEP: Trying to create another pod(pod2) with hostport 54321 but hostIP 10.0.29.34 on the node which pod1 resides and expect scheduled
STEP: Trying to create a third pod(pod3) with hostport 54321, hostIP 10.0.29.34 but use UDP protocol on the node which pod2 resides
STEP: checking connectivity from pod e2e-host-exec to serverIP: 127.0.0.1, port: 54321
Dec  4 18:49:43.207: INFO: ExecWithOptions {Command:[/bin/sh -c curl -g --connect-timeout 5 --interface 10.0.29.34 http://127.0.0.1:54321/hostname] Namespace:sched-pred-8519 PodName:e2e-host-exec ContainerName:e2e-host-exec Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Dec  4 18:49:43.208: INFO: >>> kubeConfig: /tmp/kubeconfig-941584854
Dec  4 18:49:48.375: INFO: Can not connect from e2e-host-exec to pod(pod1) to serverIP: 127.0.0.1, port: 54321
STEP: checking connectivity from pod e2e-host-exec to serverIP: 127.0.0.1, port: 54321
Dec  4 18:49:48.375: INFO: ExecWithOptions {Command:[/bin/sh -c curl -g --connect-timeout 5 --interface 10.0.29.34 http://127.0.0.1:54321/hostname] Namespace:sched-pred-8519 PodName:e2e-host-exec ContainerName:e2e-host-exec Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Dec  4 18:49:48.375: INFO: >>> kubeConfig: /tmp/kubeconfig-941584854
Dec  4 18:49:53.538: INFO: Can not connect from e2e-host-exec to pod(pod1) to serverIP: 127.0.0.1, port: 54321
STEP: checking connectivity from pod e2e-host-exec to serverIP: 127.0.0.1, port: 54321
Dec  4 18:49:53.538: INFO: ExecWithOptions {Command:[/bin/sh -c curl -g --connect-timeout 5 --interface 10.0.29.34 http://127.0.0.1:54321/hostname] Namespace:sched-pred-8519 PodName:e2e-host-exec ContainerName:e2e-host-exec Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Dec  4 18:49:53.538: INFO: >>> kubeConfig: /tmp/kubeconfig-941584854
Dec  4 18:49:58.651: INFO: Can not connect from e2e-host-exec to pod(pod1) to serverIP: 127.0.0.1, port: 54321
STEP: checking connectivity from pod e2e-host-exec to serverIP: 127.0.0.1, port: 54321
Dec  4 18:49:58.651: INFO: ExecWithOptions {Command:[/bin/sh -c curl -g --connect-timeout 5 --interface 10.0.29.34 http://127.0.0.1:54321/hostname] Namespace:sched-pred-8519 PodName:e2e-host-exec ContainerName:e2e-host-exec Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Dec  4 18:49:58.651: INFO: >>> kubeConfig: /tmp/kubeconfig-941584854
Dec  4 18:50:03.777: INFO: Can not connect from e2e-host-exec to pod(pod1) to serverIP: 127.0.0.1, port: 54321
STEP: checking connectivity from pod e2e-host-exec to serverIP: 127.0.0.1, port: 54321
Dec  4 18:50:03.777: INFO: ExecWithOptions {Command:[/bin/sh -c curl -g --connect-timeout 5 --interface 10.0.29.34 http://127.0.0.1:54321/hostname] Namespace:sched-pred-8519 PodName:e2e-host-exec ContainerName:e2e-host-exec Stdin:<nil> CaptureStdout:true CaptureStderr:true PreserveWhitespace:false Quiet:false}
Dec  4 18:50:03.777: INFO: >>> kubeConfig: /tmp/kubeconfig-941584854
Dec  4 18:50:08.954: INFO: Can not connect from e2e-host-exec to pod(pod1) to serverIP: 127.0.0.1, port: 54321
Dec  4 18:50:08.956: FAIL: Failed to connect to exposed host ports

Full Stack Trace
k8s.io/kubernetes/test/e2e.RunE2ETests(0xc003a52900)
	_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/e2e.go:130 +0x36c
k8s.io/kubernetes/test/e2e.TestE2E(0xc003a52900)
	_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/e2e_test.go:144 +0x2b
testing.tRunner(0xc003a52900, 0x4fa8ca0)
	/usr/local/go/src/testing/testing.go:1123 +0xef
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1168 +0x2b3
STEP: removing the label kubernetes.io/e2e-2dab2a44-5b13-4d39-9f68-c9bf55a898fe off the node ip-10-0-29-34
STEP: verifying the node doesn't have the label kubernetes.io/e2e-2dab2a44-5b13-4d39-9f68-c9bf55a898fe
[AfterEach] [sig-scheduling] SchedulerPredicates [Serial]
  /workspace/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:175
STEP: Collecting events from namespace "sched-pred-8519".
STEP: Found 22 events.
Dec  4 18:50:09.035: INFO: At 2020-12-04 18:49:31 +0000 UTC - event for without-label: {default-scheduler } Scheduled: Successfully assigned sched-pred-8519/without-label to ip-10-0-29-34
Dec  4 18:50:09.038: INFO: At 2020-12-04 18:49:32 +0000 UTC - event for without-label: {kubelet ip-10-0-29-34} Created: Created container without-label
Dec  4 18:50:09.038: INFO: At 2020-12-04 18:49:32 +0000 UTC - event for without-label: {kubelet ip-10-0-29-34} Started: Started container without-label
Dec  4 18:50:09.039: INFO: At 2020-12-04 18:49:32 +0000 UTC - event for without-label: {kubelet ip-10-0-29-34} Pulled: Container image "k8s.gcr.io/pause:3.2" already present on machine
Dec  4 18:50:09.041: INFO: At 2020-12-04 18:49:33 +0000 UTC - event for pod1: {default-scheduler } Scheduled: Successfully assigned sched-pred-8519/pod1 to ip-10-0-29-34
Dec  4 18:50:09.042: INFO: At 2020-12-04 18:49:33 +0000 UTC - event for without-label: {kubelet ip-10-0-29-34} SandboxChanged: Pod sandbox changed, it will be killed and re-created.
Dec  4 18:50:09.042: INFO: At 2020-12-04 18:49:33 +0000 UTC - event for without-label: {kubelet ip-10-0-29-34} Killing: Stopping container without-label
Dec  4 18:50:09.042: INFO: At 2020-12-04 18:49:34 +0000 UTC - event for pod1: {kubelet ip-10-0-29-34} Started: Started container agnhost
Dec  4 18:50:09.042: INFO: At 2020-12-04 18:49:34 +0000 UTC - event for pod1: {kubelet ip-10-0-29-34} Pulled: Container image "k8s.gcr.io/e2e-test-images/agnhost:2.21" already present on machine
Dec  4 18:50:09.044: INFO: At 2020-12-04 18:49:34 +0000 UTC - event for pod1: {kubelet ip-10-0-29-34} Created: Created container agnhost
Dec  4 18:50:09.044: INFO: At 2020-12-04 18:49:35 +0000 UTC - event for pod2: {default-scheduler } Scheduled: Successfully assigned sched-pred-8519/pod2 to ip-10-0-29-34
Dec  4 18:50:09.045: INFO: At 2020-12-04 18:49:36 +0000 UTC - event for pod2: {kubelet ip-10-0-29-34} Pulled: Container image "k8s.gcr.io/e2e-test-images/agnhost:2.21" already present on machine
Dec  4 18:50:09.045: INFO: At 2020-12-04 18:49:36 +0000 UTC - event for pod2: {kubelet ip-10-0-29-34} Created: Created container agnhost
Dec  4 18:50:09.047: INFO: At 2020-12-04 18:49:36 +0000 UTC - event for pod2: {kubelet ip-10-0-29-34} Started: Started container agnhost
Dec  4 18:50:09.047: INFO: At 2020-12-04 18:49:37 +0000 UTC - event for pod3: {default-scheduler } Scheduled: Successfully assigned sched-pred-8519/pod3 to ip-10-0-29-34
Dec  4 18:50:09.049: INFO: At 2020-12-04 18:49:38 +0000 UTC - event for pod3: {kubelet ip-10-0-29-34} Created: Created container agnhost
Dec  4 18:50:09.049: INFO: At 2020-12-04 18:49:38 +0000 UTC - event for pod3: {kubelet ip-10-0-29-34} Started: Started container agnhost
Dec  4 18:50:09.049: INFO: At 2020-12-04 18:49:38 +0000 UTC - event for pod3: {kubelet ip-10-0-29-34} Pulled: Container image "k8s.gcr.io/e2e-test-images/agnhost:2.21" already present on machine
Dec  4 18:50:09.049: INFO: At 2020-12-04 18:49:41 +0000 UTC - event for e2e-host-exec: {kubelet ip-10-0-29-34} Started: Started container e2e-host-exec
Dec  4 18:50:09.050: INFO: At 2020-12-04 18:49:41 +0000 UTC - event for e2e-host-exec: {kubelet ip-10-0-29-34} Created: Created container e2e-host-exec
Dec  4 18:50:09.050: INFO: At 2020-12-04 18:49:41 +0000 UTC - event for e2e-host-exec: {kubelet ip-10-0-29-34} Pulled: Container image "k8s.gcr.io/e2e-test-images/agnhost:2.21" already present on machine
Dec  4 18:50:09.052: INFO: At 2020-12-04 18:49:41 +0000 UTC - event for e2e-host-exec: {default-scheduler } Scheduled: Successfully assigned sched-pred-8519/e2e-host-exec to ip-10-0-29-34
Dec  4 18:50:09.057: INFO: POD            NODE           PHASE    GRACE  CONDITIONS
Dec  4 18:50:09.057: INFO: e2e-host-exec  ip-10-0-29-34  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:41 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:42 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:42 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:41 +0000 UTC  }]
Dec  4 18:50:09.058: INFO: pod1           ip-10-0-29-34  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:33 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:37 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:37 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:33 +0000 UTC  }]
Dec  4 18:50:09.058: INFO: pod2           ip-10-0-29-34  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:35 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:37 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:37 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:35 +0000 UTC  }]
Dec  4 18:50:09.058: INFO: pod3           ip-10-0-29-34  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:37 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:39 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:39 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-12-04 18:49:37 +0000 UTC  }]