JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server ------------------------------------------------------------------------------------------------- Key: TEIID-5185 URL: https://issues.jboss.org/browse/TEIID-5185 Project: Teiid Issue Type: Bug Components: JDBC Driver, Server Affects Versions: 9.3.4 Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8; Teiid Server runs on Linux. Reporter: Krum Bakalsky Assignee: Steven Hawkins Fix For: 10.2 We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients. A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level. We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server: * client successfully fetches few batches from server; * client hangs and its thread blocks on waiting for the next batch to be delivered on the network; * after 1 hour client throws exceptions that Socket is closed. When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular server hosts: jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port> Client thread's call stack: {code} "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(Unknown Source) at java.net.SocketInputStream.read(Unknown Source) at java.net.SocketInputStream.read(Unknown Source) at java.io.BufferedInputStream.fill(Unknown Source) at java.io.BufferedInputStream.read(Unknown Source) - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream) at java.io.DataInputStream.readInt(Unknown Source) at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97) at java.io.ObjectInputStream.readObject(Unknown Source) at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117) at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324) at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) at com.sun.proxy.$Proxy21.read(Unknown Source) at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427) at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449) at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382) at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227) at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142) at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253) at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510) at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535) at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174) at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) at java.lang.Thread.run(Unknown Source) Locked ownable synchronizers: - None {code} Client side exception after 1 hour: {code} 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1] at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1] at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748] at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748] at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748] at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748] at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748] at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748] at java.lang.Thread.run(Unknown Source) [?:1.8.0_121] Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?] at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4] ... 9 more Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4] at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?] at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121] at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121] at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?] at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?] at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4] ... 9 more Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4] at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?] at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121] at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121] at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?] at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?] at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4] ... 9 more Caused by: java.net.SocketException: Socket closed at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121] at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121] at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121] at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4] at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121] at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4] at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?] at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121] at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121] at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?] at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4] at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4] at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?] at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4] ... 9 more {code} Server-side log excerpt, after raising logger levels to Debug: {code} 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcherImpl.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) at sun.nio.ch.IOUtil.read(IOUtil.java:192) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447) at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880) at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354) at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112) at java.lang.Thread.run(Thread.java:745) 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed {code} Legend: * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method; * 'MessageHolder' logs are from org.teiid.net.socket.Message; * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance. The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day. We are also running JMeter in a scenario where the client is referring directly to a server URL, therefore skipping the VIP. We haven't been able to reproduce the problem in this setting so far, which suggests that the issue has something to do with the VIP setup.