{"action":"created","issue":{"url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/issues/1027","labels_url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/issues/1027/labels{/name}","comments_url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/issues/1027/comments","events_url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/issues/1027/events","html_url":"https://github.com/AsyncHttpClient/async-http-client/issues/1027","id":114745368,"number":1027,"title":"AsyncHttpClient does not close sockets under heavy load","user":{"login":"wsargent","id":71236,"avatar_url":"https://avatars.githubusercontent.com/u/71236?v=3","gravatar_id":"","url":"https://api.github.com/users/wsargent","html_url":"https://github.com/wsargent","followers_url":"https://api.github.com/users/wsargent/followers","following_url":"https://api.github.com/users/wsargent/following{/other_user}","gists_url":"https://api.github.com/users/wsargent/gists{/gist_id}","starred_url":"https://api.github.com/users/wsargent/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wsargent/subscriptions","organizations_url":"https://api.github.com/users/wsargent/orgs","repos_url":"https://api.github.com/users/wsargent/repos","events_url":"https://api.github.com/users/wsargent/events{/privacy}","received_events_url":"https://api.github.com/users/wsargent/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/labels/Defect","name":"Defect","color":"e11d21"},{"url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/labels/Netty","name":"Netty","color":"009800"}],"state":"open","locked":false,"assignee":null,"milestone":{"url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/milestones/65","html_url":"https://github.com/AsyncHttpClient/async-http-client/milestones/1.9.32","labels_url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/milestones/65/labels","id":1299330,"number":65,"title":"1.9.32","description":"","creator":{"login":"slandelle","id":849197,"avatar_url":"https://avatars.githubusercontent.com/u/849197?v=3","gravatar_id":"","url":"https://api.github.com/users/slandelle","html_url":"https://github.com/slandelle","followers_url":"https://api.github.com/users/slandelle/followers","following_url":"https://api.github.com/users/slandelle/following{/other_user}","gists_url":"https://api.github.com/users/slandelle/gists{/gist_id}","starred_url":"https://api.github.com/users/slandelle/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/slandelle/subscriptions","organizations_url":"https://api.github.com/users/slandelle/orgs","repos_url":"https://api.github.com/users/slandelle/repos","events_url":"https://api.github.com/users/slandelle/events{/privacy}","received_events_url":"https://api.github.com/users/slandelle/received_events","type":"User","site_admin":false},"open_issues":1,"closed_issues":5,"state":"open","created_at":"2015-09-10T12:56:39Z","updated_at":"2015-11-03T12:18:13Z","due_on":"2015-09-29T22:00:00Z","closed_at":null},"comments":6,"created_at":"2015-11-03T05:34:26Z","updated_at":"2015-11-05T06:41:55Z","closed_at":null,"body":"If you create 1000 requests in a very short time frame and use connection pool with AsyncHttpClient 1.9.21 and Netty 3.10.1, then some sockets will leak and stay open even past the idle socket reaper.  This was initially filed as https://github.com/playframework/playframework/issues/5215, but can be replicated without Play WS.\r\n\r\nCreated a reproducing test case here: https://github.com/wsargent/asynchttpclient-socket-leak\r\n\r\nif you have 50 requests, then they'll all be closed immediately.\r\nif you have 1000 requests, they'll stay open for a while.\r\nAfter roughly two minutes, AHC will close off all idle sockets, but up to 30 will never die and will always be established.\r\n\r\nTo see the dangling sockets, run the id of the java process:\r\n\r\n```\r\nsudo lsof -i | grep 31602\r\n```\r\n\r\nYou'll see\r\n\r\n```\r\njava      31602       wsargent   89u  IPv6 0xe1b25a8062380645      0t0  TCP 192.168.1.106:58646->ec2-54-173-126-144.compute-1.amazonaws.com:https (ESTABLISHED)\r\n```\r\n\r\nThe client port number is your key into the application: if you search for \"58646\" in application.log, then you'll see that there's a connection associated with it:\r\n\r\n```\r\n2015-11-02 20:41:38,496 [DEBUG] from org.jboss.netty.handler.logging.LoggingHandler in New I/O worker #1 - [id: 0x5650b318, /192.168.1.106:58646 => playframework.com/54.173.126.144:443] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=2357, cap=2357)\r\n```\r\n\r\nYou can see the lifecycle of a handle by using grep:\r\n\r\n```\r\ngrep \"0x5650b318\" application.log\r\n```\r\n\r\nand what's interesting is that while most ids will have a `CLOSE` / `CLOSED` lifecycle associated with them:\r\n\r\n```\r\n2015-11-02 20:41:45,878 [DEBUG] from org.jboss.netty.handler.logging.LoggingHandler in Hashed wheel timer #1 - [id: 0x34804fcc, /192.168.1.106:59122 => playframework.com/54.173.126.144:443] WRITE: BigEndianHeapChannelBuffer(ridx=0, widx=69, cap=69)\r\n2015-11-02 20:41:46,427 [DEBUG] from org.jboss.netty.handler.logging.LoggingHandler in New I/O worker #2 - [id: 0x34804fcc, /192.168.1.106:59122 => playframework.com/54.173.126.144:443] CLOSE\r\n2015-11-02 20:41:46,427 [DEBUG] from org.jboss.netty.handler.logging.LoggingHandler in New I/O worker #2 - [id: 0x34804fcc, /192.168.1.106:59122 :> playframework.com/54.173.126.144:443] DISCONNECTED\r\n2015-11-02 20:41:46,434 [DEBUG] from org.jboss.netty.handler.logging.LoggingHandler in New I/O worker #2 - [id: 0x34804fcc, /192.168.1.106:59122 :> playframework.com/54.173.126.144:443] UNBOUND\r\n2015-11-02 20:41:46,434 [DEBUG] from org.jboss.netty.handler.logging.LoggingHandler in New I/O worker #2 - [id: 0x34804fcc, /192.168.1.106:59122 :> playframework.com/54.173.126.144:443] CLOSED\r\n```\r\n\r\nIn the case of \"0x5650b318\", there's no CLOSE event happening here.  In addition, there's a couple of lines that say it's a cached channel:\r\n\r\n```\r\n2015-11-02 20:41:33,340 [DEBUG] from com.ning.http.client.providers.netty.request.NettyRequestSender in default-akka.actor.default-dispatcher-4 - Using cached Channel [id: 0x5650b318, /192.168.1.106:58646 => playframework.com/54.173.126.144:443]\r\n2015-11-02 20:41:33,340 [DEBUG] from com.ning.http.client.providers.netty.request.NettyRequestSender in default-akka.actor.default-dispatcher-4 - Using cached Channel [id: 0x5650b318, /192.168.1.106:58646 => playframework.com/54.173.126.144:443]\r\n```\r\n\r\nSo I think Netty is not closing cached channels even if they are idle, in some circumstances."},"comment":{"url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/issues/comments/153970648","html_url":"https://github.com/AsyncHttpClient/async-http-client/issues/1027#issuecomment-153970648","issue_url":"https://api.github.com/repos/AsyncHttpClient/async-http-client/issues/1027","id":153970648,"user":{"login":"slandelle","id":849197,"avatar_url":"https://avatars.githubusercontent.com/u/849197?v=3","gravatar_id":"","url":"https://api.github.com/users/slandelle","html_url":"https://github.com/slandelle","followers_url":"https://api.github.com/users/slandelle/followers","following_url":"https://api.github.com/users/slandelle/following{/other_user}","gists_url":"https://api.github.com/users/slandelle/gists{/gist_id}","starred_url":"https://api.github.com/users/slandelle/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/slandelle/subscriptions","organizations_url":"https://api.github.com/users/slandelle/orgs","repos_url":"https://api.github.com/users/slandelle/repos","events_url":"https://api.github.com/users/slandelle/events{/privacy}","received_events_url":"https://api.github.com/users/slandelle/received_events","type":"User","site_admin":false},"created_at":"2015-11-05T06:41:55Z","updated_at":"2015-11-05T06:41:55Z","body":"@jroper I'm really sorry, but I think I won't be able to investigate this myself before something like 2 weeks. swamped :weary: \r\nSo yes, it would be great if you guys could land a hand. I can cut 1.9.32 when you want."}}