[infinispan-issues] [JBoss JIRA] (ISPN-3452) Hot Rod client socket leak

[ https://issues.jboss.org/browse/ISPN-3452?page=com.atlassian.jira.plugin.... ] Michal Linhard commented on ISPN-3452: -------------------------------------- BTW this is a hotrod client problem, but ISPN JIRA project still hasn't Client component defined so I've put it under "Remote protocols" This is not a very well formed test but it reproduces the situation I'm talking about: https://github.com/mlinhard/infinispan/commit/839022bad269565282bfc3b4df3... I'm creating a server that just simply closes all the connections it accepts and an idle RemoteCacheManager that just sits there and it's evictor thread creates a new TcpTransport object every 500ms, pings the server and gets TransportException("End of stream reached!") which is swallowed. sample output here (TRACE on org.infinispan.client.hotrod) {code} 2013-08-29 18:21:46,215 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Created tcp transport: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35552], serverAddress=/127.0.0.1:15233, id =3} 2013-08-29 18:21:46,216 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Returning to pool: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35552], serverAddress=/127.0.0.1:15233, id =3} 2013-08-29 18:21:46,249 INFO (main) [org.infinispan.client.hotrod.HotRodSocketLeakTest] numActive = 0, numIdle=1 2013-08-29 18:21:46,708 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Fetching from pool: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35552], serverAddress=/127.0.0.1:15233, id =3} 2013-08-29 18:21:46,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] About to validate(ping) connection to server /127.0.0.1:15233. TcpTransport is TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35552], serverAddress=/127.0.0.1:15233, id =3} 2013-08-29 18:21:46,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 160 2013-08-29 18:21:46,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 12 2013-08-29 18:21:46,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 23 2013-08-29 18:21:46,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote 0 bytes 2013-08-29 18:21:46,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 3 2013-08-29 18:21:46,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 0 2013-08-29 18:21:46,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.protocol.Codec12] Wrote header for message 3. Operation code: 0x17. Flags: 0x0 2013-08-29 18:21:46,710 TRACE (ScumbagServer) [org.infinispan.client.hotrod.test.ScumbagServer] Reading and closing 2013-08-29 18:21:46,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Flushed socket: Socket[addr=/127.0.0.1,port=15233,localport=35552] 2013-08-29 18:21:46,711 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Read byte -1 from socket input in Socket[addr=/127.0.0.1,port=15233,localport=35552] 2013-08-29 18:21:46,712 TRACE (ScumbagServer) [org.infinispan.client.hotrod.test.ScumbagServer] Accepting new connection 2013-08-29 18:21:46,712 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Created tcp transport: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35553], serverAddress=/127.0.0.1:15233, id =4} 2013-08-29 18:21:46,712 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Returning to pool: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35553], serverAddress=/127.0.0.1:15233, id =4} 2013-08-29 18:21:47,209 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Fetching from pool: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35553], serverAddress=/127.0.0.1:15233, id =4} 2013-08-29 18:21:47,209 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] About to validate(ping) connection to server /127.0.0.1:15233. TcpTransport is TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35553], serverAddress=/127.0.0.1:15233, id =4} 2013-08-29 18:21:47,210 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 160 2013-08-29 18:21:47,210 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 12 2013-08-29 18:21:47,210 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 23 2013-08-29 18:21:47,210 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote 0 bytes 2013-08-29 18:21:47,210 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 3 2013-08-29 18:21:47,210 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 0 2013-08-29 18:21:47,211 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.protocol.Codec12] Wrote header for message 4. Operation code: 0x17. Flags: 0x0 2013-08-29 18:21:47,211 TRACE (ScumbagServer) [org.infinispan.client.hotrod.test.ScumbagServer] Reading and closing 2013-08-29 18:21:47,211 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Flushed socket: Socket[addr=/127.0.0.1,port=15233,localport=35553] 2013-08-29 18:21:47,212 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Read byte -1 from socket input in Socket[addr=/127.0.0.1,port=15233,localport=35553] 2013-08-29 18:21:47,212 TRACE (ScumbagServer) [org.infinispan.client.hotrod.test.ScumbagServer] Accepting new connection 2013-08-29 18:21:47,213 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Created tcp transport: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35554], serverAddress=/127.0.0.1:15233, id =5} 2013-08-29 18:21:47,213 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Returning to pool: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35554], serverAddress=/127.0.0.1:15233, id =5} 2013-08-29 18:21:47,249 INFO (main) [org.infinispan.client.hotrod.HotRodSocketLeakTest] numActive = 0, numIdle=1 2013-08-29 18:21:47,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Fetching from pool: TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35554], serverAddress=/127.0.0.1:15233, id =5} 2013-08-29 18:21:47,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] About to validate(ping) connection to server /127.0.0.1:15233. TcpTransport is TcpTransport{socket=Socket[addr=/127.0.0.1,port=15233,localport=35554], serverAddress=/127.0.0.1:15233, id =5} 2013-08-29 18:21:47,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 160 2013-08-29 18:21:47,709 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 12 2013-08-29 18:21:47,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 23 2013-08-29 18:21:47,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote 0 bytes 2013-08-29 18:21:47,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 3 2013-08-29 18:21:47,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 0 2013-08-29 18:21:47,710 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.protocol.Codec12] Wrote header for message 5. Operation code: 0x17. Flags: 0x0 2013-08-29 18:21:47,711 TRACE (ScumbagServer) [org.infinispan.client.hotrod.test.ScumbagServer] Reading and closing 2013-08-29 18:21:47,711 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Flushed socket: Socket[addr=/127.0.0.1,port=15233,localport=35554] 2013-08-29 18:21:47,711 TRACE (Timer-0) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Read byte -1 from socket input in Socket[addr=/127.0.0.1,port=15233,localport=35554] {code} Normally we should also see "Successfully closed socket" message after TcpTransport is destroyed. but that doesn't happen. good tool to see that Sockets are still open is http://file-leak-detector.kohsuke.org/ (pointed out by Mitchell on the forum) -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira