Teiid client 8.10.0.Final intermittently hangs when processing multi-batch query to Teiid server 9.3.4

[hungrykoala]

Hello Teiid community,

Allow me to bring to your attention a recent problem we have started facing between two applications, one acting as a Teiid client (version is 8.10.0.Final), and the other one being a Teiid server (version 9.3.4). The client connects to the server using server's JDBC endpoint, and leveraging Apache DBCP connection pool; it then fires off SQL requests to it. If that might be relevant to the scenario, the server instances actually sit behind a VIP load balancer, which is what the client refers to (rather than directly to some server instance).

The major source of complexity here is that the problem we're hitting is very difficult to reproduce, it takes hours of persistently triggering requests to reach a single occurrence of the issue. Moreover, the described setup has been like that for long time now, while hitting these problems started happening only recently.

The problem is that certain queries, usually being served within a couple of seconds' time, intermittently time out after 1 hour. We've taken some regular thread dumps from the client process, during that one hour period, and here's the client thread's call stack:

Worker16045_QueryProcessorQueue1316447" - Thread t@108468
   java.lang.Thread.State: RUNNABLE
 at java.net.SocketInputStream.socketRead0(Native Method)
 at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
 at java.net.SocketInputStream.read(SocketInputStream.java:170)
 at java.net.SocketInputStream.read(SocketInputStream.java:141)
 at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
 at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
 - locked <78696d53> (a org.teiid.core.util.AccessibleBufferedInputStream)
 at java.io.DataInputStream.readInt(DataInputStream.java:387)
 at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
 at java.io.ObjectInputStream.readObject(ObjectInputStream.java:365)
 at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:118)
 - locked  (a java.lang.Object)
 at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:307)
 at sun.reflect.GeneratedMethodAccessor75.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:497)
 at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
 at com.sun.proxy.$Proxy75.read(Unknown Source)
 at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:406)
 at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:439)
 at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:373)
 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:500)
 at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:254)
 at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
 at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)

 at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.handleBatch(ConnectorWorkItem.java:396)
 at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.more(ConnectorWorkItem.java:214)
 - locked <61e500d> (a org.teiid.dqp.internal.datamgr.ConnectorWorkItem)
 at sun.reflect.GeneratedMethodAccessor79.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:497)
 at org.teiid.dqp.internal.datamgr.ConnectorManager$1.invoke(ConnectorManager.java:209)
 at com.sun.proxy.$Proxy73.more(Unknown Source)
 at org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:301)
 at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:110)
 at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:107)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:58)
 at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:276)
 at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
 at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
 at java.lang.Thread.run(Thread.java:745)
   Locked ownable synchronizers:
 - locked <4465cde1> (a java.util.concurrent.ThreadPoolExecutor$Worker)

(The reason why this call stack is a bit involved, and served by Teiid DQP logic, is because our client application also acts as a Teiid server, and simply delegates incoming queries to the Teiid server. However this is not relevant to the problem, as we have managed to reproduce the issue via a simple JMeter-powered JDBC client against the Teiid server).

This stays like that for the whole 1 hour, from which it is evident that while asking the server for the next batch of the result set, the client blocks on reading the data from the network socket, hangs, and eventually times out.

We raised the level of the server loggers to debug, and here is a snippet from the activity of the server-side thread that handled this request:

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

Due to specifics of the logging format, the classes that these messages originated from are not logged. However I believe that:

• '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.

In the beginning NIO36 thread successfully served batches to the client, between 12:00:45.617 and 12:00:48.932, which is approx. 3 seconds, after which it started logging only following line, roughly once every 3.5 mins:

2017-12-15 12:02:18.386 [NIO36       ] DEBUG - Channel closed 

which continued all the way up to 13:00:52.143 when it hit the exception problem. As there is no record in the logs with finalRow being positive (only finalRow=-1), it is evident that the last batch was never served to the client, hence the result set never got fully exhausted at the server side.

Finally, the exception that gets logged at client side after 1 hour is as attached. Basically the connection timeout expires, and likely the client resets it - which is what the server logged.

Could you please let us know if that behaviour rings some bells, have you observed something like that before?

Is the 9.3.4 server compatible with the 8.10.0.Final client?

Is this a matter of configuring the client/server so that the multi-batch query gets successfully served?

Any hints where/what to look at?

All my best,

Krum.

[shawkins]

> Could you please let us know if that behaviour rings some bells, have you observed something like that before?

Seems the same as [TEIID-5054] autoFailover with a multi-batch result timing issue - JBoss Issue Tracker

> Is the 9.3.4 server compatible with the 8.10.0.Final client?

Yes it is considered compatible, but any existing issue such as this one will not have been addressed by a community release on 8.10.x - can you try a later client 9.2.x, 9.3.x, or 10.0.x latest?

> Is this a matter of configuring the client/server so that the multi-batch query gets successfully served?

No it is excepted that this should work without additional configuration.

[hungrykoala]

Thank you, Steven, for your blazingly fast answer!

Looking at the documentation I see that the connection property autoFailover is set to false by default. We also don't specify it explicitly in the JDBC connection string at client side. Actually we don't list all the service instance hosts behind the VIP, but just refer to the VIP itself:

url = "jdbc:teiid:<ServiceName>@mm://<VIP's DNS name>:<VIP's port>"

Indeed, we ran intensive JMeter testing with 10.0.0 at client side - no issues occurred. After intensive testing with 8.10.0 client, we got only one reproduce.

By 'intense' I don't really mean hammering the service, but simply running the query frequently, for hours, until we hit the problem; successful runs are anyway taking only few seconds.

Maybe we could check VIP logs, around the time of problem occurrence, to see if something fishy happened, like request from the client IP suddenly being routed to a different service host than before?

[shawkins]

> Maybe we could check VIP logs, around the time of problem occurrence, to see if something fishy happened, like request from the client IP suddenly being routed to a different service host than before?

If you can't reproduce this with later clients that's good.  I'm not exactly sure how this would be triggered in this scenario - especially so infrequently, but it does have the same symptom as the jira issue.  The read loop has an issue which effectively causes a timeouts in io operations when a ping is issued during the results processing.

Are there any additional logs from the server that indicate a communication issue?

[hungrykoala]

Unfortunately that's pretty much all the logs we were able to scrape from the server.

Are you suggesting that the ping thread is being used in the client even when autoFailover is false? Is there any evidence that could prove that, like certain log messages issued by that thread, or simply somehow identify it within client's thread dumps - what's its name?

Have a great weekend, and merry holidays!

Krum.

Update: here are two threads in our thread dumps that might be relevant:

"Teiid Timer" - Thread t@363
   java.lang.Thread.State: WAITING
 at java.lang.Object.wait(Native Method)
 - waiting on <1ec6fbb6> (a java.util.TaskQueue)
 at java.lang.Object.wait(Object.java:502)
 at java.util.TimerThread.mainLoop(Timer.java:526)
 at java.util.TimerThread.run(Timer.java:505)
   Locked ownable synchronizers:
 - None

"SocketPing" - Thread t@544
   java.lang.Thread.State: TIMED_WAITING
 at java.lang.Object.wait(Native Method)
 - waiting on <12c80fbf> (a java.util.TaskQueue)
 at java.util.TimerThread.mainLoop(Timer.java:552)
 at java.util.TimerThread.run(Timer.java:505)
   Locked ownable synchronizers:
 - None

[shawkins]

> Are you suggesting that the ping thread is being used in the client even when autoFailover is false? Is there any evidence that could prove that, like certain log messages issued by that thread, or simply somehow identify it within client's thread dumps - what's its name?

The ping thread is always in use even when autoFailover is false.   The jira issue about autoFailover=true is that a ping is sent to proactively ensure connection health by the thread reading results while in a read loop that doesn't expect recurrent access.  I'm not aware of a similar situation when autoFailover is false, but the fix either way would prevents the io processing from getting into this state.

From your logs all we see is:

1. 2017-12-15 12:00:48.932 [NIO36       ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest 
2. 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1

Then the timeouts.  It doesn't appear that any other message is involved - just a typical request/response and then silence from the client.  Are those all of the debug messages from the org.teiid.TRANSPORT context for that time?

> Update: here are two threads in our thread dumps that might be relevant:

Those appear to be just the normal wait loops of the Timer class.

> Have a great weekend, and merry holidays!

Thanks, hope you had a good weekend as well.

[hungrykoala]

Thank you, Steven, for your answers.

> The ping thread is always in use even when autoFailover is false.  The jira issue about autoFailover=true is that a ping is sent to proactively ensure connection health by the thread reading results while in a read loop that doesn't expect recurrent access.  I'm not aware of a similar situation when autoFailover is false, but the fix either way would prevents the io processing from getting into this state.

OK, I see. Seems like this thread's activity might still interfere with the one that's reading batches in loop, even when the flag is turned off. Are you planning to downport the fix to the 8.10.0 version series?

> Are those all of the debug messages from the org.teiid.TRANSPORT context for that time?

Yes, that's everything. I also checked the signature of healthy conversations between client & server, and they usually end up with smth like:

2017-12-15 11:59:48.266 [ocessorQueue14016117] DEBUG - send message: MessageHolder: key=550223 contents=ResultsMessage rowCount=1 finalRow=1
2017-12-15 11:59:48.267 [NIO54      ] DEBUG - processing message:MessageHolder: key=550224 contents=Invoke interface org.teiid.client.DQP.closeRequest
2017-12-15 11:59:48.268 [NIO54      ] DEBUG - send message: MessageHolder: key=550224 contents=null

In our case we have no signs of DQP.closeRequest calls which means that communication simply hanged at some point.

Attributing this to a race condition between ping & reader threads is consistent with observing that issue so rarely.

[shawkins]

> OK, I see. Seems like this thread's activity might still interfere with the one that's reading batches in loop, even when the flag is turned off. Are you planning to downport the fix to the 8.10.0 version series?

No, the recommendation would be to upgrade the client.

> Attributing this to a race condition between ping & reader threads is consistent with observing that issue so rarely.

Hopefully it's along those lines and already addressed.  I'll try to recreate this scenario as well to see if can recreate it.

[hungrykoala]

OK, I see. Thanks for these clarifications.

I guess we can close this chat now. We're not completely sure, but likely the problem is as suspected.

[hungrykoala]

Unfortunately we were just able to reproduce the problem from a JMeter client, using the Teiid 9.3.4 JDBC driver (Teiid server is also on version 9.3.4).

JMeter client thread:

"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

An hour later JMeter logged the following:

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

[shawkins]

Please open a JIRA issue on this as we work toward a resolution.  With your latest reproduction are you showing that this occurs for you with just the stock client / server - no special networking or client flags set?

[hungrykoala]

OK, thanks. Sure, I will report a JIRA so you could prioritize looking into it.

> With your latest reproduction are you showing that this occurs for you with just the stock client / server - no special networking or client flags set?

Yes. Nothing special about the setup, besides the fact that the Teiid server application sits behind a VIP load balancer.

[hungrykoala]

Created [TEIID-5185] JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server - JBoss I…