{"action":"created","issue":{"url":"https://api.github.com/repos/linkerd/linkerd/issues/1178","repository_url":"https://api.github.com/repos/linkerd/linkerd","labels_url":"https://api.github.com/repos/linkerd/linkerd/issues/1178/labels{/name}","comments_url":"https://api.github.com/repos/linkerd/linkerd/issues/1178/comments","events_url":"https://api.github.com/repos/linkerd/linkerd/issues/1178/events","html_url":"https://github.com/linkerd/linkerd/issues/1178","id":219291564,"number":1178,"title":"Leaking connection on 500 retrys","user":{"login":"taer","id":458866,"avatar_url":"https://avatars2.githubusercontent.com/u/458866?v=3","gravatar_id":"","url":"https://api.github.com/users/taer","html_url":"https://github.com/taer","followers_url":"https://api.github.com/users/taer/followers","following_url":"https://api.github.com/users/taer/following{/other_user}","gists_url":"https://api.github.com/users/taer/gists{/gist_id}","starred_url":"https://api.github.com/users/taer/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/taer/subscriptions","organizations_url":"https://api.github.com/users/taer/orgs","repos_url":"https://api.github.com/users/taer/repos","events_url":"https://api.github.com/users/taer/events{/privacy}","received_events_url":"https://api.github.com/users/taer/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":9,"created_at":"2017-04-04T15:33:36Z","updated_at":"2017-04-27T22:05:07Z","closed_at":null,"body":"Posting this as a followup to a Slack conversation with Alex. This is against 0.9.0 of linkerd\r\n\r\nWe are noticing that linkerd's connection pool for certain endpoints grows rapidly during error conditions, then doesn't shrink. When the same app gets a burst of normal traffic, the pool shrinks back to 0 fairly quickly.\r\n\r\nThe timeline is:\r\n* Request comes in. We send that request to linkerd.\r\n* Linkerd returns an error to us after 20 seconds(our request timeout)\r\n* Connection pool has ~83 idle connections that do not disappear\r\n* metrics.json showed 83 500 status errors and 83 ResponseClassificationSyntheticException\r\n* a `netstat -atpn | grep <L5d.pid> | grep CLOSE_WAIT` shows 83 sockets in CLOSE_WAIT\r\n* It happened on Friday, and the connections are still there the following Monday\r\n\r\nThe service recovered, and is still working now. The connection pool number is correct, linkerd is holding onto CLOSE_WAIT sockets. This will eventually become an issue requiring a restart.\r\n\r\nThis happened 2 times, so the numbers in the attached metrics.json are a bit different. This also occurred on 3 separate linkerd instances at about the same time. The cause was the way the downstream app responded, but it affected 3 independent linkerds. Alex identified this in slack:\r\n> I think you got stuck in a retry loop.  `\"rt/cgp/dst/path/svc/live/appName/retries/total\": 274,`  something about that one request triggered a 5xx response from the server and it kept being retried and failing until either the retry budget was exhausted or the request timed out\r\n> it looks like there were 99 requests, 97 of which were successful, and 2 of which were failures and those failures triggered 274 retries\r\n\r\nWe have retryableRead500 tuned on, which is likely the reason for the large number of connections. This is a server in our staging environment, so it gets very little traffic. In the case of the error, a single request came in that caused 83 abandoned connections.\r\n\r\n[metrics.json](https://github.com/linkerd/linkerd/files/893581/metrics.txt)\r\nCompare number of connections in metrics with CLOSE_WAIT\r\n```\r\nroot@ip-10-122-17-136:~# netstat -atpn | grep 3887 |grep CLOSE_WAIT |wc\r\n    166    1162   16102\r\n```\r\nShowing all CLOSE_WAIT are to the server that errored out.\r\n```\r\nroot@ip-10-122-17-136:~# netstat -atpn | grep 3887 |grep CLOSE_WAIT | grep 10.122.3.77:31392|wc\r\n    166    1162   16102\r\n```\r\n\r\nAnd this server is still serving traffic on that ip:port. We just had some sort of disruption for this brief window.\r\n\r\nI have the metrics being captured by datadog, so we have how the metrics changed on a 30 second window.\r\nThis shows the connection count\r\n![connections](https://cloud.githubusercontent.com/assets/458866/24664304/ec543702-191f-11e7-9619-52947e9a7bd6.png)\r\nThis shows the count of 500 errors\r\n![500statuscounter](https://cloud.githubusercontent.com/assets/458866/24664343/06d4148a-1920-11e7-8194-064e68bb22a8.png)\r\nAnd this is the bytes_sent stat for the application\r\n![bytespersec](https://cloud.githubusercontent.com/assets/458866/24664371/1bd1434e-1920-11e7-8c58-e6665f01097b.png)\r\n \r\n\r\n# Debugging attempts\r\nWe attempted to see if using the connections would result in them being cleaned up. I flooded a server that had 159 connections and 159 sockets in CLOSE_WAIT. The pool grew to 360+, then returned back to 159\r\n\r\n# Dead sockets\r\nThis is a sample of netstat showing the dead sockets that match the leaked connection counts\r\n```\r\ntcp        1      0 10.122.8.59:56734       10.122.3.77:31392       CLOSE_WAIT  4228/java       \r\ntcp        1      0 10.122.8.59:35906       10.122.3.77:31392       CLOSE_WAIT  4228/java \r\n```\r\n\r\n\r\n# Linkerd log\r\n```2017/03/31 18:17:11 I 0331 18:17:11.572 UTC THREAD25 TraceId:4f2d95dc50b33383: FailureAccrualFactory marking connection to \"#/consul/us-east-1-vpc-XXXX/live/appName\" as dead\r\n. Remote Address: Inet(/10.122.3.77:31392,Map())\r\n2017/03/31 18:17:16 I 0331 18:17:16.862 UTC THREAD24 TraceId:4f2d95dc50b33383: FailureAccrualFactory marking connection to \"#/consul/us-east-1-vpc-XXXX/live/appName\" as dead\r\n. Remote Address: Inet(/10.122.3.77:31392,Map())\r\n2017/03/31 18:17:26 I 0331 18:17:26.970 UTC THREAD23 TraceId:4f2d95dc50b33383: FailureAccrualFactory marking connection to \"#/consul/us-east-1-vpc-XXXX/live/appName\" as dead\r\n. Remote Address: Inet(/10.122.3.77:31392,Map())\r\n2017/03/31 18:17:30 E 0331 18:17:30.874 UTC THREAD10: service failure\r\n2017/03/31 18:17:30 com.twitter.finagle.IndividualRequestTimeoutException: exceeded 20.seconds to 0.0.0.0/4140 while waiting for a response for an individual request, excluding retries. Remo\r\nte Info: Not Available\r\n2017/03/31 18:17:30\r\n2017/03/31 18:17:31 E 0331 18:17:31.060 UTC THREAD24 TraceId:4f2d95dc50b33383: service failure\r\n2017/03/31 18:17:31 Failure(20.seconds, flags=0x03) with RemoteInfo -> Upstream Address: /127.0.0.1:54910, Upstream Client Id: Not Available, Downstream Address: /10.122.3.77:31392, Downstream Client Id: #/consul/us-east-1-vpc-XXXX/live/appName, Trace Id: 4f2d95dc50b33383.4f2d95dc50b33383<:4f2d95dc50b33383\r\n2017/03/31 18:17:31 Caused by: com.twitter.util.TimeoutException: 20.seconds\r\n2017/03/31 18:17:31     at com.twitter.util.Future$$anonfun$within$1.apply(Future.scala:992)\r\n```\r\n\r\n# Config file\r\n```\r\nadmin:\r\n  port: 9990\r\nrouters:\r\n- protocol: http\r\n  httpAccessLog: /opt/proxy/logs/access.log\r\n  label: cgp\r\n  timeoutMs: 2000\r\n  identifier:\r\n  - kind: io.l5d.header\r\n    header: X-Route-Id\r\n  interpreter:\r\n    kind: io.l5d.namerd\r\n    dst: /$/inet/namerd/4100\r\n    namespace: header\r\n  responseClassifier:\r\n    kind: io.l5d.retryableRead5XX\r\n  client:\r\n    loadBalancer:\r\n      kind: ewma\r\n    failureAccrual:\r\n      kind: io.l5d.successRate\r\n      successRate: 0.9\r\n      requests: 20\r\n      backoff:\r\n        kind: constant\r\n        ms: 10000\r\n  servers:\r\n  - port: 4140\r\n    ip: 0.0.0.0\r\n```\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/linkerd/linkerd/issues/comments/297852168","html_url":"https://github.com/linkerd/linkerd/issues/1178#issuecomment-297852168","issue_url":"https://api.github.com/repos/linkerd/linkerd/issues/1178","id":297852168,"user":{"login":"adleong","id":3979810,"avatar_url":"https://avatars3.githubusercontent.com/u/3979810?v=3","gravatar_id":"","url":"https://api.github.com/users/adleong","html_url":"https://github.com/adleong","followers_url":"https://api.github.com/users/adleong/followers","following_url":"https://api.github.com/users/adleong/following{/other_user}","gists_url":"https://api.github.com/users/adleong/gists{/gist_id}","starred_url":"https://api.github.com/users/adleong/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/adleong/subscriptions","organizations_url":"https://api.github.com/users/adleong/orgs","repos_url":"https://api.github.com/users/adleong/repos","events_url":"https://api.github.com/users/adleong/events{/privacy}","received_events_url":"https://api.github.com/users/adleong/received_events","type":"User","site_admin":false},"created_at":"2017-04-27T22:05:07Z","updated_at":"2017-04-27T22:05:07Z","body":"I've posted what I believe is a fix at https://github.com/linkerd/linkerd/pull/1256\r\n\r\n@taer @fantayeneh @leozc I would love your help testing this fix a verifying if it solves the issue for you.  Let me know if you'd like me to build a binary or docker image for you.\r\n\r\n@fantayeneh I wasn't able to reproduce this with non-chunked responses.  Do you have a sample implementation of a server that causes this?  "}}
{"actor":{"display_login":"adleong"}}