[
https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin...
]
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)