EC2 lookup fails Network Route component startup in explicit proxy environment

[nhoughto]

Using kube-router-0.2.0-beta.9 on Kubernetes 1.9.9 in an AWS environment that requires an explicit proxy kube-router fails to start the network route controller and fails to properly report the fact it hasn't started, and doesn't appear to fail health checks?

It appears as part of the network route startup an EC2 check is done, in an environment where EC2 API access is only allowed through a proxy, this call will timeout with this error:

Failed to disable source destination check due to: RequestError: send request failed caused by: Post https://ec2.ap-southeast-2.amazonaws.com/: dial tcp 54.240.195.243:443: i/o timeout

But doesn't progress any further, or fail a healthcheck. My assumption is any outbound call should have a realistic timeout on it, and should fail startup / healthchecks if it fails.

Full startup log:

I0722 23:43:37.722380       1 kube-router.go:186] Running /usr/local/bin/kube-router version v0.2.0-beta.9, built on 2018-07-12T20:56:27+0000, go1.8.7
I0722 23:43:37.725898       1 health_controller.go:145] Starting health controller
I0722 23:43:38.338426       1 network_policy_controller.go:125] Starting network policy controller
I0722 23:43:38.357521       1 network_services_controller.go:250] Starting network services controller
E0722 23:46:39.941020       1 aws.go:61] Failed to disable source destination check due to: RequestError: send request failed
caused by: Post https://ec2.ap-southeast-2.amazonaws.com/: dial tcp 54.240.195.243:443: i/o timeout

If I set environment variables https_proxy etc, the call succeeds and the network route starts up properly:

I0722 23:34:37.054957       1 kube-router.go:186] Running /usr/local/bin/kube-router version v0.2.0-beta.9, built on 2018-07-12T20:56:27+0000, go1.8.7
I0722 23:34:37.058283       1 health_controller.go:145] Starting health controller
I0722 23:34:37.669651       1 network_policy_controller.go:125] Starting network policy controller
I0722 23:34:37.688415       1 network_services_controller.go:250] Starting network services controller
E0722 23:34:38.303122       1 aws.go:58] Node does not have necessary IAM creds to modify instance attribute. So skipping disabling src-dst check.
I0722 23:34:38.318332       1 network_routes_controller.go:199] Starting network route controller
I0722 23:34:38.322797       1 network_routes_controller.go:676] Could not find BGP peer info for the node in the node annotations so skipping configuring peer.
time="2018-07-22T23:34:38Z" level=info msg="Add a peer configuration for:10...." Topic=Peer
time="2018-07-22T23:34:54Z" level=info msg="skipped asn negotiation: peer-as: 64512, peer-type: internal" Key=10.... State=BGP_FSM_OPENSENT Topic=Peer
time="2018-07-22T23:34:54Z" level=info msg="Peer Up" Key=10.... State=BGP_FSM_OPENCONFIRM Topic=Peer
I0722 23:34:54.668324       1 network_routes_controller.go:365] Found node: 10.... to be in different subnet.
I0722 23:34:54.668471       1 network_routes_controller.go:410] Tunnel interface: tun-10... for the node 10.... already exists.

[nhoughto]

Hmm actually i just didn't wait long enough, it did eventually come up, the shortest time i saw was ~6mins, longest was 10+mins. So much less bad than I originally thought. Still an optional EC2 call shouldn't block startup for 6mins, workaround is to set proxy envs obv 👍

I0722 23:43:37.722380       1 kube-router.go:186] Running /usr/local/bin/kube-router version v0.2.0-beta.9, built on 2018-07-12T20:56:27+0000, go1.8.7
I0722 23:43:37.725898       1 health_controller.go:145] Starting health controller
I0722 23:43:38.338426       1 network_policy_controller.go:125] Starting network policy controller
I0722 23:43:38.357521       1 network_services_controller.go:250] Starting network services controller
E0722 23:46:39.941020       1 aws.go:61] Failed to disable source destination check due to: RequestError: send request failed
caused by: Post https://ec2.ap-southeast-2.amazonaws.com/: dial tcp 54.240.195.243:443: i/o timeout
E0722 23:48:42.726044       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:48:47.726071       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:48:52.726047       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:48:57.726043       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:02.726119       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:07.726126       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:12.726100       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:17.726043       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:22.726042       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:27.726085       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:32.726103       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:37.726049       1 health_controller.go:119] Network Routing Controller heartbeat missed
E0722 23:49:42.204011       1 aws.go:61] Failed to disable source destination check due to: RequestError: send request failed
caused by: Post https://ec2.ap-southeast-2.amazonaws.com/: dial tcp 54.240.195.243:443: i/o timeout
E0722 23:49:42.726040       1 health_controller.go:119] Network Routing Controller heartbeat missed
I0722 23:49:43.221245       1 network_routes_controller.go:199] Starting network route controller
I0722 23:49:43.226330       1 network_routes_controller.go:676] Could not find BGP peer info for the node in the node annotations so skipping configuring peer.
time="2018-07-22T23:49:43Z" level=info msg="Add a peer configuration for:10.." Topic=Peer
time="2018-07-22T23:49:59Z" level=info msg="skipped asn negotiation: peer-as: 64512, peer-type: internal" Key=10.. State=BGP_FSM_OPENSENT Topic=Peer
time="2018-07-22T23:49:59Z" level=info msg="Peer Up" Key=10.. State=BGP_FSM_OPENCONFIRM Topic=Peer
I0722 23:49:59.280551       1 network_routes_controller.go:365] Found node: 10.. to be in different subnet.

[nhoughto]

I think this is a problem in 0.1.0 as well.

[roffe]

@nhoughto could you please document the steps you did to get http_proxy working properly so we can add it as a example to the doc's When running in an AWS environment that requires an explicit proxy:

[nhoughto]

Just the standard way to define environment variables on a pod:
https://kubernetes.io/docs/tasks/inject-data-application/define-environment-variable-container/

and then standard proxy env variables - Proxy environment variables:
https://ec.haxx.se/usingcurl-proxies.html

[roffe]

@nhoughto thank you. i've added a section to the user-guide with regards to this