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

[Michal Linhard (JIRA)]

    [ https://issues.jboss.org/browse/ISPN-3452?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12800342#comment-12800342 ] 

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/839022bad269565282bfc3b4df3ee760e4812562

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)
                
> Hot Rod client socket leak
> --------------------------
>
>                 Key: ISPN-3452
>                 URL: https://issues.jboss.org/browse/ISPN-3452
>             Project: Infinispan
>          Issue Type: Bug
>          Components: Remote protocols
>    Affects Versions: 5.3.0.Final, 6.0.0.Alpha3
>            Reporter: Michal Linhard
>            Assignee: Galder Zamarreño
>            Priority: Critical
>
> TransportObjectFactory.validateObject swallows TransportException and doesn't properly close socket connected with the TcpTransport object.
> This way an open socket is leaked each time it's created by connection pool Evictor thread

--
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