[teiid-issues] [JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from server
Krum Bakalsky (JIRA)
issues at jboss.org
Tue Dec 19 12:25:00 EST 2017
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Krum Bakalsky updated TEIID-5185:
---------------------------------
Description:
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 service 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.
W
was:
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.
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.
> JDBC client intermittently hangs when processing multi-batch result sets from 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
>
> 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 service 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.
> W
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the teiid-issues
mailing list