{"action":"created","issue":{"url":"https://api.github.com/repos/kubernetes/kubernetes/issues/32551","repository_url":"https://api.github.com/repos/kubernetes/kubernetes","labels_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/32551/labels{/name}","comments_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/32551/comments","events_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/32551/events","html_url":"https://github.com/kubernetes/kubernetes/issues/32551","id":176553173,"number":32551,"title":"Low nf_conntrack_tcp_timeout_close_wait default causes intermittent ECONNREFUSED on GKE","user":{"login":"porridge","id":489420,"avatar_url":"https://avatars.githubusercontent.com/u/489420?v=3","gravatar_id":"","url":"https://api.github.com/users/porridge","html_url":"https://github.com/porridge","followers_url":"https://api.github.com/users/porridge/followers","following_url":"https://api.github.com/users/porridge/following{/other_user}","gists_url":"https://api.github.com/users/porridge/gists{/gist_id}","starred_url":"https://api.github.com/users/porridge/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/porridge/subscriptions","organizations_url":"https://api.github.com/users/porridge/orgs","repos_url":"https://api.github.com/users/porridge/repos","events_url":"https://api.github.com/users/porridge/events{/privacy}","received_events_url":"https://api.github.com/users/porridge/received_events","type":"User","site_admin":false},"labels":[{"id":116712108,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/area/networking","name":"area/networking","color":"006b75","default":false},{"id":128716589,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/component/kube-proxy","name":"component/kube-proxy","color":"0052cc","default":false},{"id":116719829,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/component/kubelet","name":"component/kubelet","color":"0052cc","default":false},{"id":114528223,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/priority/P1","name":"priority/P1","color":"eb6420","default":false},{"id":173493827,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/team/cluster","name":"team/cluster","color":"d2b48c","default":false}],"state":"closed","locked":false,"assignee":{"login":"bowei","id":837034,"avatar_url":"https://avatars.githubusercontent.com/u/837034?v=3","gravatar_id":"","url":"https://api.github.com/users/bowei","html_url":"https://github.com/bowei","followers_url":"https://api.github.com/users/bowei/followers","following_url":"https://api.github.com/users/bowei/following{/other_user}","gists_url":"https://api.github.com/users/bowei/gists{/gist_id}","starred_url":"https://api.github.com/users/bowei/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bowei/subscriptions","organizations_url":"https://api.github.com/users/bowei/orgs","repos_url":"https://api.github.com/users/bowei/repos","events_url":"https://api.github.com/users/bowei/events{/privacy}","received_events_url":"https://api.github.com/users/bowei/received_events","type":"User","site_admin":false},"assignees":[{"login":"bowei","id":837034,"avatar_url":"https://avatars.githubusercontent.com/u/837034?v=3","gravatar_id":"","url":"https://api.github.com/users/bowei","html_url":"https://github.com/bowei","followers_url":"https://api.github.com/users/bowei/followers","following_url":"https://api.github.com/users/bowei/following{/other_user}","gists_url":"https://api.github.com/users/bowei/gists{/gist_id}","starred_url":"https://api.github.com/users/bowei/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bowei/subscriptions","organizations_url":"https://api.github.com/users/bowei/orgs","repos_url":"https://api.github.com/users/bowei/repos","events_url":"https://api.github.com/users/bowei/events{/privacy}","received_events_url":"https://api.github.com/users/bowei/received_events","type":"User","site_admin":false}],"milestone":{"url":"https://api.github.com/repos/kubernetes/kubernetes/milestones/23","html_url":"https://github.com/kubernetes/kubernetes/milestones/v1.5","labels_url":"https://api.github.com/repos/kubernetes/kubernetes/milestones/23/labels","id":1945978,"number":23,"title":"v1.5","description":"","creator":{"login":"lavalamp","id":647318,"avatar_url":"https://avatars.githubusercontent.com/u/647318?v=3","gravatar_id":"","url":"https://api.github.com/users/lavalamp","html_url":"https://github.com/lavalamp","followers_url":"https://api.github.com/users/lavalamp/followers","following_url":"https://api.github.com/users/lavalamp/following{/other_user}","gists_url":"https://api.github.com/users/lavalamp/gists{/gist_id}","starred_url":"https://api.github.com/users/lavalamp/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lavalamp/subscriptions","organizations_url":"https://api.github.com/users/lavalamp/orgs","repos_url":"https://api.github.com/users/lavalamp/repos","events_url":"https://api.github.com/users/lavalamp/events{/privacy}","received_events_url":"https://api.github.com/users/lavalamp/received_events","type":"User","site_admin":false},"open_issues":227,"closed_issues":645,"state":"open","created_at":"2016-08-16T21:47:28Z","updated_at":"2016-11-16T18:50:38Z","due_on":"2016-12-09T00:00:00Z","closed_at":null},"comments":22,"created_at":"2016-09-13T05:32:10Z","updated_at":"2016-11-16T18:50:38Z","closed_at":"2016-11-16T18:50:37Z","body":"**Kubernetes version** (use `kubectl version`):\nClient Version: version.Info{Major:\"1\", Minor:\"3\", GitVersion:\"v1.3.5\", GitCommit:\"b0deb2eb8f4037421077f77cb163dbb4c0a2a9f5\", GitTreeState:\"clean\", BuildDate:\"2016-08-11T20:29:08Z\", GoVersion:\"go1.6.2\", Compiler:\"gc\", Platform:\"linux/amd64\"}\nServer Version: version.Info{Major:\"1\", Minor:\"3\", GitVersion:\"v1.3.5\", GitCommit:\"b0deb2eb8f4037421077f77cb163dbb4c0a2a9f5\", GitTreeState:\"clean\", BuildDate:\"2016-08-11T20:21:58Z\", GoVersion:\"go1.6.2\", Compiler:\"gc\", Platform:\"linux/amd64\"}\n\n**Environment**:\n- **Cloud provider or hardware configuration**: GKE\n- **OS** (e.g. from /etc/os-release): PRETTY_NAME=\"Debian GNU/Linux 7 (wheezy)\"\n- **Kernel** (e.g. `uname -a`):3.16.0-4-amd64\n\n**What happened**:\n\nWe're seeing plenty of \"connection refused\" errors when connecting to the GCE metadata server from within pods in our GKE cluster. These connections are mostly from OAuth2 client libraries (in Go and Python) trying to fetch access token when connecting to any GCP service. However as explained below, this can happen to connections to other services as well.\n\nExample (this one from Cloud SQL proxy):\n\n```\n2016/09/08 06:37:10 couldn't connect to \"[project]:us-central1:[db-name]\": Post https://www.googleapis.com/sql/v1beta4/projects/[project]/instances/[db-name]/createEphemeral?alt=json: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token: dial tcp 169.254.169.254:80: getsockopt: connection refused\n```\n\n**What you expected to happen**:\n\nNo intermittent failures.\n\n**How to reproduce it** (as minimally and precisely as possible):\n1. Create plenty of TCP connections from pods to a single host:port. Leave the connections half-closed by the remote end, do not close it from the other side.\n2. Let these `CLOSE_WAIT` connections expire from node conntrack tables.\n3. Create more such connections, and eventually node's netfilter will reuse a NAT source port which is still in use in the remote end's mind. Such connections will be reset by the remote end, resulting in \"connection refused\" errors on the userspace side.\n\n**Anything else do we need to know**:\n\nTL;DR: kernel's default nf_conntrack_tcp_timeout_close_wait of 60s is too low: http://marc.info/?l=netfilter-devel&m=117568928824030&w=2\n\nI caught this with tcpdump on our GKE cluster. Here it is, with additional lines (the ones with 5-second resolution) from conntrack(1) outputs for the interesting 5-tuple.\nActors:\n- 10.192.2.35 is a pod IP\n- 10.241.0.49 is the node IP\n- 169.254.169.254 is the GCE metadata server\n\npod 10.192.2.35 starts a connection, it's NATed to node source port 35715\n\n```\n09:13:55.069526 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [S], seq 1235205249, win 29200, options [mss 1460,sackOK,TS val 148646959 ecr 0,nop,wscale 7], length 0\n09:13:55.069696 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [S.], seq 3311972373, ack 1235205250, win 65535, options [mss 1420,eol], length 0\n09:13:55.069742 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 1, win 29200, length 0\n```\n\nconnection is established. HTTP request:\n\n```\n09:13:55.069982 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [P.], seq 1:216, ack 1, win 29200, length 215\n09:13:55.070112 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 216, win 65320, length 0\n09:13:55.070127 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 216, win 65535, length 0\n```\n\nHTTP response:\n\n```\n09:13:55.070411 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [P.], seq 1:510, ack 216, win 65535, length 509\n09:13:55.070441 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 510, win 30016, length 0\n```\n\nanother HTTP request:\n\n```\n09:13:55.071634 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [P.], seq 216:464, ack 510, win 30016, length 248\n09:13:55.071731 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 464, win 65287, length 0\n09:13:55.071763 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 464, win 65535, length 0\n```\n\nand another HTTP response:\n\n```\n09:13:55.071936 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [P.], seq 510:955, ack 464, win 65535, length 445\n09:13:55.108816 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 955, win 31088, length 0\n```\n\ntime passes, conntrack sees the connection as established:\n\n```\n09:13:59    tcp  6 86395 ESTABLISHED src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:04    tcp  6 86390 ESTABLISHED src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:09    tcp  6 86385 ESTABLISHED src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:14    tcp  6 86380 ESTABLISHED src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:19    tcp  6 86375 ESTABLISHED src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:24    tcp  6 86370 ESTABLISHED src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n```\n\nafter 30s of inactivity metadata server closes its side of the connection\n\n```\n09:14:25.073869 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [F.], seq 955, ack 464, win 65535, length 0\n```\n\nand client acks that:\n\n```\n09:14:25.112831 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 956, win 31088, length 0\n```\n\nbut does not close its side of connection yet\n\ntime passes, and conntrack sees the connection as half-closed (a.k.a. close_wait):\n\n```\n09:14:29    tcp  6 55 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:34    tcp  6 50 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:40    tcp  6 44 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:45    tcp  6 39 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:50    tcp  6 34 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:14:55    tcp  6 29 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:15:00    tcp  6 24 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:15:05    tcp  6 19 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:15:10    tcp  6 14 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:15:15    tcp  6 9 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n09:15:21    tcp  6 4 CLOSE_WAIT src=10.192.2.35 dst=169.254.169.254 sport=35715 dport=80 src=169.254.169.254 dst=10.241.0.49 sport=80 dport=35715 [ASSURED] mark=0 use=1\n```\n\nafter a minute, though (nf_conntrack_tcp_timeout_close_wait sysctl knob's default), it loses patience and drops the entry from the conntrack table.\nAs a result, the connection is no longer NATed any more, and when the client wakes up 2.5 minutes later to close the connection, it shows up with its non-NATed source IP:\n\n```\n09:17:00.019964 IP 10.192.2.35.35715 > 169.254.169.254.80: Flags [F.], seq 1235205713, ack 3311973329, win 31088, length 0\n```\n\nobviously the metadata server TCP stack explains there is no connection for such 5-tuple, with an RST bit:\n\n```\n09:17:00.020053 IP 169.254.169.254.80 > 10.192.2.35.35715: Flags [R], seq 3311973329, win 65535, length 0\n```\n\nSo at this point the \"TCP 10.241.0.49.35715 > 169.254.169.254.80\" connection is still open in metadata server's mind, since the FIN above did not change anything.\n\nTherefore 59 minutes later, when the node happily maps a completely different connection (made from a different pod) to the same source port:\n\n```\n10:14:14.639439 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [S], seq 301038175, win 29200, options [mss 1460,sackOK,TS val 149551851 ecr 0,nop,wscale 7], length 0\n```\n\nHowever since the metadata server still remembers the old connection, and the sequence numbers and the state of the connection do not match, so it rejects the connection attempt with an RST:\n\n```\n10:14:14.639520 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [R.], seq 982994923, ack 3360800223, win 65535, length 0\n```\n\nThis is seen in userspace as \"connection refused\".\n\nInterestingly, just ten minutes later there is yet another connection attempt, NATed to the same source port, and at this point apparently the metadata server no longer remembers the old connection, as it accepts the new one.\n\nThis suggests the CLOSE_WAIT lifetime on metadata server is between 59 and 69 minutes, probably 60.\n\n```\n10:24:18.059755 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [S], seq 3149308939, win 29200, options [mss 1460,sackOK,TS val 149702706 ecr 0,nop,wscale 7], length 0\n10:24:18.060016 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [S.], seq 146596554, ack 3149308940, win 65535, options [mss 1420,eol], length 0\n10:24:18.060075 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 1, win 29200, length 0\n10:24:18.060180 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [P.], seq 1:193, ack 1, win 29200, length 192\n10:24:18.060375 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 193, win 65343, length 0\n10:24:18.060392 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 193, win 65535, length 0\n10:24:18.060661 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [P.], seq 1:271, ack 193, win 65535, length 270\n10:24:18.060724 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 271, win 30016, length 0\n10:24:18.061528 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [F.], seq 193, ack 271, win 30016, length 0\n10:24:18.061647 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [.], ack 194, win 65535, length 0\n10:24:18.061674 IP 169.254.169.254.80 > 10.241.0.49.35715: Flags [F.], seq 271, ack 194, win 65535, length 0\n10:24:18.061695 IP 10.241.0.49.35715 > 169.254.169.254.80: Flags [.], ack 272, win 30016, length 0\n```\n"},"comment":{"url":"https://api.github.com/repos/kubernetes/kubernetes/issues/comments/261035929","html_url":"https://github.com/kubernetes/kubernetes/issues/32551#issuecomment-261035929","issue_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/32551","id":261035929,"user":{"login":"thockin","id":5595220,"avatar_url":"https://avatars.githubusercontent.com/u/5595220?v=3","gravatar_id":"","url":"https://api.github.com/users/thockin","html_url":"https://github.com/thockin","followers_url":"https://api.github.com/users/thockin/followers","following_url":"https://api.github.com/users/thockin/following{/other_user}","gists_url":"https://api.github.com/users/thockin/gists{/gist_id}","starred_url":"https://api.github.com/users/thockin/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/thockin/subscriptions","organizations_url":"https://api.github.com/users/thockin/orgs","repos_url":"https://api.github.com/users/thockin/repos","events_url":"https://api.github.com/users/thockin/events{/privacy}","received_events_url":"https://api.github.com/users/thockin/received_events","type":"User","site_admin":false},"created_at":"2016-11-16T18:50:37Z","updated_at":"2016-11-16T18:50:37Z","body":"@bowei can you tweak the subject of #35919 to be a better release note?  Specifically the default value of that param?"}}
{"actor":{"display_login":"thockin"}}