cc @kubernetes/sig-node-pr-reviews

This makes sense to me and is a minimal solution.

stackdriver flake
/retest

Latest revision looks really clearly done to me

/assign @derekwaynecarr

this is a critical bug fix, and labeling appropriately for 1.8 milestone.

/approve
/lgtm

/test pull-kubernetes-e2e-gce-etcd3

@liggitt @alexef I believe the issue described in in #41916 is actually an issue with the underlying TCP connection. The fix in this merge implements a timeout on the HTTP request, and does not close and set up a new TCP connection right?

This is also discussed in kubernetes-retired/kube-aws#598

This does not force closing the TCP connection, but does establish a new one (as demonstrated by the accompanying test, which hangs the first TCP connection and ensures a separate connection is established)

@liggitt @RyPeck experiment shows that the connection is NOT reestablished on a K8s 1.8.3 cluster. Simple way to try it out on a kubelet is start dropping all packets destined to the API, and then observe how long it takes for the "ESTABLISHED" connection to disappear and new connection attempts to appear.

We've also had a 1.8.3 cluster go crazy for some 18 minutes when ELB was scaled down and half of the ELB "endpoints" disappeared. Investigation points to kubelet not bothering to re-establish connections to the live nodes.

What we did see happening was 10-second spaced retries/failures from kubelet to report its status, which result in an timeout waiting for HTTP response This particular timeout, however, does not result in the connection being re-established - the next attempt is simply reusing the same TCP pipe.

If I read the attached test correctly, it ensures that each status update attempt itself is timed out, and that there are multiple attempts happening. This does not prove that the TCP connection is reestablished.

We also encountered the problem referenced in #48638 on 1.7.8. This PR did not resolve the issue.

This does not prove that the TCP connection is reestablished.

The attempt counter is only incremented when a new connection is established. Does that not demonstrate that the timeout causes the hung connection to be abandoned and a new connection created?

We also encountered the problem referenced in #48638 on 1.7.8. This PR did not resolve the issue.

Can you give more details or a reproducer, possibly as an additional unit test in the same vein as the one included in this PR?

Can you give more details or a reproducer, possibly as an additional unit test in the same vein as the one included in this PR?

Sure, let me start with details.

Environment: AWS, Kubernetes 1.7.8, CoreOS 1576.4.0. HA masters behind an ELB.
Event: The master ELB changes IPs, as confirmed by AWS CloudTrail. Immediately, all kubelets start reporting:

E1227 22:45:20.510774    3983 kubelet_node_status.go:357] Error updating node status, will retry: error getting node "ip-10-188-36-106.ec2.internal": Get https://k8s.vpc.gh.internal/api/v1/nodes/ip-10-188-36-106.ec2.internal: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

Shortly thereafter, the controller manager reports:

I1227 22:45:37.638923       9 event.go:218] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"ip-10-188-36-106.ec2.internal", UID:"e1c2c442-e4e0-11e7-927b-124b89f5bfb0", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'NodeNotReady' Node ip-10-188-36-106.ec2.internal status is now: NodeNotReady

This happens on each kubelet and there is now a production outage due to #45126.

We restart kubelets on all worker nodes and now this happens:

I1227 22:49:58.239809       9 event.go:218] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"ip-10-188-36-106.ec2.internal", UID:"e1c2c442-e4e0-11e7-927b-124b89f5bfb0", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'DeletingAllPods' Node ip-10-188-36-106.ec2.internal event: Deleting all Pods from Node ip-10-188-36-106.ec2.internal.

The pods take several minutes to get rescheduled and restarted, resolving the outage.

We have since switched to NLBs, mitigating this particular failure mode. However, we still occasionally see individual nodes become NotReady, with the same logs. In the absence of operator intervention, each event lasts about 15 minutes, which corroborates #41916 (comment). Logging onto an affected node and curling the API endpoint manually returns the response as expected.

The best reproduction steps I can suggest at this time are here: #41916 (comment). I'll look into reproducing the specific ELB condition in a cloud provider independent way as well.

I was able to catch one of these with tcpdump today. Here's the relevant section:

The kubelet (10.188.48.76) stops communicating with the apiserver (10.188.21.18) at 12:03:24. It reports an error updating node status at 12:03:34 and continues until restarted at 12:06:39.

In the interval between 12:03:24 and 12:06:39, there is no new TCP connection established and the only communication between the kubelet and the apiserver is a backoff of TCP retransmissions.

Hi all, is there any update on this issue ?
We encountered those hangs on kubernetes 1.6.x where the fix was not backported, but reading the recent feedbacks, it seems an upgrade to 1.7/1.8 won't guarantee it will 100% resolve it.

Any mitigation recommendation ? We are seeing this often in our cluster as well.

Under 1.9.3 and 1.7.12, we are still seeing this failure cause an outage of a large fraction of production nodes roughly every week or two, across nine clusters in six different AWS regions.

Here's a procedure to reproduce the problem under controlled conditions on Kubernetes 1.9.3. I'm not sure how to turn this into a unit test, yet.

Intent:

In production, we see load balancers in front of the apiserver become unresponsive and stop sending ACKs on established TCP connections. After ~15 minutes, the kubelet socket's TCP retransmission delay is exhausted, the kernel considers the connection failed, and the Go runtime establishes a new TCP connection.

15 minutes is much longer than the usual node-status-update-frequency/node-monitor-grace-period. We need to identify and recover from this failure on the scale of 10-30s. The patch in #52176 attempts to meet this requirement by setting a ~10s HTTP request timeout on the client sending node status updates.

This procedure demonstrates that the kubelet cannot recover from a stalled TCP connection even though #52176 works as intended. The test simulates the effects of a remote TCP socket becoming unresponsive (not sending ACKs) by interposing a local TCP proxy between kubelet and apiserver, then suspending the proxy child process handling the connection. This doesn't precisely reproduce the production failure: in the test the remote socket continues sending ACKs, and as a consequence, the TCP retransmission timeout is never hit and the local socket never fails.

Even so, we can reliably get the kubelet to fail.

Procedure:

1. Start with a running cluster node with a healthy kubelet. In one local terminal, observe node health:
   kubectl get $node -w
2. Start two terminal sessions to the victim node.
3. In terminal session A, start a socat session to proxy TCP traffic. Make sure to enable fork behavior on the listening socket to handle multiple connections:
   socat -d -d -d TCP4-LISTEN:60443,fork TCP4:$apiserver_ip:443
4. In terminal session B, update your kubelet configuration to point to 127.0.0.1:60443. You may have to add an entry to the node's /etc/hosts to convince the TLS client that this is a valid address for the apiserver's cert.
5. In session B, bounce the kubelet so it's going through your local proxy. In session A you should now see socat logging healthy connection information. The node should still be healthy in the apiserver; pause to verify this if needed.
6. In session B, identify the child process spawned by socat to handle the active TCP connection. I used this command to discover it:
   ps -u"$USER" -opid,ppid,pgrp,cmd
7. In session B, pause (do not terminate) the socat child process.
   kill -s TSTP $childpid
8. When the node heartbeat timeout/retries have expired you should see the node become NotReady. The kubelet will log something like this, repeating ad nauseam:

kubelet_node_status.go:383] Error updating node status, will retry: error getting node "ip-10-31-100-133": Get https://controller:60443/api/v1/nodes/ip-10-31-100-133?resourceVersion=0: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
kubelet_node_status.go:383] Error updating node status, will retry: error getting node "ip-10-31-100-133": Get https://controller:60443/api/v1/nodes/ip-10-31-100-133: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
kubelet_node_status.go:383] Error updating node status, will retry: error getting node "ip-10-31-100-133": Get https://controller:60443/api/v1/nodes/ip-10-31-100-133: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
kubelet_node_status.go:383] Error updating node status, will retry: error getting node "ip-10-31-100-133": Get https://controller:60443/api/v1/nodes/ip-10-31-100-133: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
kubelet_node_status.go:383] Error updating node status, will retry: error getting node "ip-10-31-100-133": Get https://controller:60443/api/v1/nodes/ip-10-31-100-133: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
kubelet_node_status.go:375] Unable to update node status: update node status exceeds retry count

9. In session B, show that a new TCP session succeeds against the same local proxy port:
   kubectl --kube-config /etc/kubernetes/kubeconfig.yaml get nodes
10. In session B, bounce the kubelet. The new kubelet process will establish a new connection and the node will recover. You can also verify recovery by terminating the stopped proxy process with kill -s 9 $childpid or by reviving the stopped proxy with kill -s CONT $childpid.

Summary:

A stalled TCP connection to the apiserver still brings down an active node, with all the consequences outlined in kubernetes-retired/kube-aws#598, #41916, #48638, #44557, #48670, and Financial-Times/content-k8s-provisioner@d290fea.

I'm not sure where else to put responsibility for maintaining this connection, so my first suggestion would be to have HeartbeatClient force its connection(s) to close on request timeout.

@jfoy - Just for me to understand, you're whole cluster basically busts right? We're seeing the same thing where nodes go into NotReady and all of the sudden the entire cluster can't do anything.

@bobbytables Often not the entire cluster, but a big swath of it, yeah. It seems to be random based on which IP address each node's kubelet resolved the ELB name to, the last time it had to start a connection to the apiserver. The nodes drop out for ~15 minutes then suddenly recover, causing much of the load on the cluster to be rescheduled.

@bobbytables Often not the entire cluster, but a big swath of it, yeah. It seems to be random based on which IP address each node's kubelet resolved the ELB name to, the last time it had to start a connection to the apiserver. The nodes drop out for ~15 minutes then suddenly recover, causing much of the load on the cluster to be rescheduled.

Cool, I'm literally sitting in a post-mortem room talking about this. I'm copying your note.

@jfoy @bobbytables we noticed that it tended to occur by availability zone.

This appears to describe the upstream bug: kubernetes/client-go#342

@jfoy we just finished troubleshooting exactly the same issue with AWS NLB in US-East1 with a number of different clusters (mix of 1.7.8 and 1.9.3) #61917

Semi-random event that seems to have started to get worse in the last couple of weeks, to the extent that I'm seeing it multiple times per day now. Seems to happen more often at night. Suspect the sheer over-utilization in the region is driving reduced network quality, increasing chance of socket failure.

@stephbu Thanks, that's really useful to know (and disappointing!)

The unit test here assumes a good TCP connection, which might not be in real case.

@zhouhaibing089 That's right. The problem seems to occur when the kernel thinks the socket is still good and is in a TCP retransmission-retry state. I suspect there's a way to recreate that situation in a unit test via raw sockets, but I haven't had time to develop that idea.

I'm afraid I haven't had any time to look into this further and write a concrete test case, but in case it's helpful: as I mentioned in #48670 (comment) we have been running that patch in production since August and have not seen this issue re-occur.

We observed the same issue as reported in #48670, tested the PR for our case and all works. Is there a possibility of reopening the PR as it appears others could benefit from it?

We've moved over to NLBs entirely and we're still hitting the issue on a node-by-node basis. I'm going to see what we can do for additional instrumentation to find out who's dropping the ball between the apiserver, the NLB, and the kubelet.

EDIT: moving conversation over to #48638