Uploaded image for project: 'Teiid'
  1. Teiid
  2. TEIID-5185

JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server

    Details

    • Type: Bug
    • Status: Resolved (View Workflow)
    • Priority: Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 9.3.4
    • Fix Version/s: None
    • Component/s: JDBC Driver, Server
    • Labels:
      None
    • 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.

      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 server hosts:
      jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>

      Client thread's call stack:

      "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  
      

      Client side exception after 1 hour:

      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  
      

      Server-side log excerpt, after raising logger levels to Debug:

      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  
      

      Legend:

      • 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
      • 'MessageHolder' logs are from org.teiid.net.socket.Message;
      • the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.

      The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.

      We are also running JMeter in a scenario where the client is referring directly to a server URL, therefore skipping the VIP. We haven't been able to reproduce the problem in this setting so far, which suggests that the issue has something to do with the VIP setup.

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                shawkins Steven Hawkins
                Reporter:
                hungrykoala Krum Bakalsky
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: