0 Replies Latest reply on Dec 13, 2019 5:08 AM by Srikanth Dyapa

    JDBC driver taking too much time (after AWS RDS failover) to close stale connection from pool

    Srikanth Dyapa

      In IBM liberty server I have configured the datasource with oracle connection details like below.

      <dataSource id="auditLogDatasource" jndiName="jdbc/audit_log" type="javax.sql.DataSource" validationTimeout="10s"> 
           <jdbcDriver libraryRef="OracleLib"/>  <properties.oracle description="main db pipe" URL="jdbc:oracle:thin://@localhost:1686/mkapp" password="test" user="test"/>
           <connectionManager id="ConnectionManager" maxPoolSize="30" minPoolSize="1" purgePolicy="FailingConnectionOnly" />
      </dataSource>

      Java code

      @Resource(lookup = "jdbc/audit_log") 
      public void setDataSource(DataSource dataSource)
      {
           if (this.dataSource == null) { this.dataSource = dataSource; }
      } 
      public void store(@Observes AuditRecord auditRecord) {
           Connection con = null;
           PreparedStatement preparedStatement = null;
           try {
                log
      .info("DB connection requested");
                con
      = this.dataSource.getConnection();
                preparedStatement
      = con.prepareStatement(INSERT_QUERY);
                int index = 1;
                preparedStatement
      .setString(index++, auditRecord.getAction());
                preparedStatement
      .setString(index++, auditRecord.getUserInitiating());
                preparedStatement
      .setString(index++, auditRecord.getUserAffected());
                preparedStatement
      .setString(index++, auditRecord.getAdditionalInfo());
                preparedStatement
      .setTimestamp(index++, new Timestamp(auditRecord.getCreateTime().getTime()));
                preparedStatement
      .setString(index++, auditRecord.getServer());
                preparedStatement
      .executeUpdate();
                log
      .info("DB record added");
           } catch (Exception e) {
                log
      .error(e.getMessage(), e);
           } finally {
                if (preparedStatement != null) {
                     try {
                          preparedStatement
      .close();
                     } catch (SQLException e) {
                          log
      .error(e.getMessage(), e);
                     }
                }
                if (con != null) {
                     try {
                          con
      .close();
                     } catch (SQLException e) {
                          log
      .error(e.getMessage(), e);
                     }
                }
           }
      }

       

      Initially everything working fine mostly I am seeing only 1 Free connection count.

      But once I trigger AWS RDS failover (Reboot with failover) server taking too much time to discard the invalid connection from pool & creating new connection.

      2019/11/15 17:31:28.571 [Default Executor-thread-60] INFO dao.AuditDao : DB connection requested 
      2019/11/15 17:47:03.741 [Default Executor-thread-60] INFO dao.AuditDao : DB record added

      error in message.log after 16 min

      [ERROR   ] J2CA0081E: Method destroy failed while trying to execute method destroy on ManagedConnection WSRdbManagedConnectionImpl@10e0477e 
      from resource
      No longer available. Caught exception: com.ibm.ws.rsadapter.exceptions.DataStoreAdapterException:
      DSRA0080E
      : An exception was received by the Data Store Adapter. See original exception message: {0}. with SQL State : 08000 SQL Code : 17410
      at com
      .ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.destroy(WSRdbManagedConnectionImpl.java:2513)
      at
      [internal classes]
      at com
      .test.auth.dao.AuditDao.store(AuditDao.java:38)
      at sun
      .reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun
      .reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      at sun
      .reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java
      .lang.reflect.Method.invoke(Method.java:498)
      at org
      .jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
      at
      [internal classes]
      at com
      .test.auth.AuthHomeServlet.audit(AuthHomeServlet.java:72)
      at com
      .test.auth.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
      at javax
      .servlet.http.HttpServlet.service(HttpServlet.java:707)
      at javax
      .servlet.http.HttpServlet.service(HttpServlet.java:790)
      at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1255)
      at
      [internal classes]
      at com
      .test.auth.UserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
      at com
      .ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
      at
      [internal classes] Caused by: java.sql.SQLRecoverableException: No more data to read from socket DSRA0010E: SQL State = 08000, Error Code = 17,410
      at oracle
      .jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1157)
      at oracle
      .jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:350)
      at oracle
      .jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)
      at oracle
      .jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:61)
      at oracle
      .jdbc.driver.T4CConnection.logoff(T4CConnection.java:574)
      at oracle
      .jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:4011)
      at com
      .ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.destroy(WSRdbManagedConnectionImpl.java:2508) ... 17 more

      Is there any way that I can configure the connection close timeout ? though I configured the validationTimeout seems like it is not working.

      Liberty version: 17.0.0.4 
      Database product version : Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
      JDBC driver version 
      : 12.1.0.2.0 Driver lib: ojdbc6.jar / ojdbc7.jar

      This is what I got from thread dump

      Default Executor-thread-29" #87 daemon prio=5 os_prio=31 tid=0x00007fa06793d800 nid=0x13d03 waiting for monitor entry [0x0000700012743000]
        java
      .lang.Thread.State: BLOCKED (on object monitor)
        at oracle
      .jdbc.driver.PhysicalConnection.isProxySession(PhysicalConnection.java:4398)
        
      - waiting to lock <0x00000007bd6d0900> (a oracle.jdbc.driver.T4CConnection)
        at sun
      .reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun
      .reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun
      .reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java
      .lang.reflect.Method.invoke(Method.java:498)
        at com
      .ibm.ws.rsadapter.impl.OracleHelper.doConnectionCleanup(OracleHelper.java:354)
        at com
      .ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanupStates(WSRdbManagedConnectionImpl.java:2847)
        at com
      .ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanup(WSRdbManagedConnectionImpl.java:2774)
        at com
      .ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1541)
        at com
      .ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:459)
        at com
      .ibm.ejs.j2c.PoolManager.reserve(PoolManager.java:1602)
        at com
      .ibm.ejs.j2c.ConnectionManager.allocateMCWrapper(ConnectionManager.java:581)
        at com
      .ibm.ejs.j2c.ConnectionManager.allocateConnection(ConnectionManager.java:314)
        at com
      .ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:138)
        at com
      .ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:112)
        at test
      .dao.AuditDao.store(AuditDao.java:38)
        at sun
      .reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun
      .reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun
      .reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java
      .lang.reflect.Method.invoke(Method.java:498)
        at org
      .jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
        at org
      .jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:78)
        at org
      .jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:129)
        at org
      .jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:299)
        at org
      .jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:277)
        at org
      .jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:255)
        at org
      .jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:269)
        at org
      .jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:258)
        at org
      .jboss.weld.event.EventImpl.fire(EventImpl.java:92)
        at test
      .AuthHomeServlet.audit(AuthHomeServlet.java:72)
        at test
      .AuthHomeServlet.doPost(AuthHomeServlet.java:37)
        at javax
      .servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax
      .servlet.http.HttpServlet.service(HttpServlet.java:790)
        at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1230)
        at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:729)
        at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:426)
        at com
      .ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:182)
        at com
      .ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:93)
        at test
      .MkidUserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
        at com
      .ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
        at com
      .ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:90)
        at com
      .ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:1001)
        at com
      .ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1139)
        at com
      .ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1010)
        at com
      .ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:75)
        at com
      .ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:938)
        at com
      .ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:279)
        at com
      .ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1136)
        at com
      .ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:417)
        at com
      .ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:376)
        at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:548)
        at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:482)
        at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:347)
        at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:318)
        at com
      .ibm.ws.channel.ssl.internal.SSLConnectionLink.determineNextChannel(SSLConnectionLink.java:1077)
        at com
      .ibm.ws.channel.ssl.internal.SSLConnectionLink$MyReadCompletedCallback.complete(SSLConnectionLink.java:656)
        at com
      .ibm.ws.channel.ssl.internal.SSLReadServiceContext$SSLReadCompletedCallback.complete(SSLReadServiceContext.java:1803)
        at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:503)
        at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:573)
        at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:954)
        at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1043)
        at com
      .ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:239)
        at java
      .util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java
      .util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java
      .lang.Thread.run(Thread.java:748)

        
      Locked ownable synchronizers:
        
      - <0x00000007822c8b38> (a java.util.concurrent.ThreadPoolExecutor$Worker)

      From requestTiming feature

      [11/17/19 20:03:22:442 AEDT] 000000ee com.ibm.ws.request.timing.manager.SlowRequestManager         
      W TRAS0112W
      : Request AAAcI1bXZti_AAAAAAAAAAD has been running on thread 000000df for at least 30016.328ms.
      The following stack trace shows what this thread is currently running. 
      at sun
      .reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun
      .reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:95)
      at sun
      .reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
      at java
      .lang.reflect.Method.invoke(Method.java:508)
      at com
      .ibm.ws.rsadapter.impl.OracleHelper.doConnectionCleanup(OracleHelper.java:355)
      at com
      .ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanupStates(WSRdbManagedConnectionImpl.java:2752)
      at com
      .ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.cleanup(WSRdbManagedConnectionImpl.java:2679)
      at com
      .ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1492)
      at com
      .ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:444)
      at com
      .ibm.ejs.j2c.PoolManager.reserve(PoolManager.java:1543)
      at com
      .ibm.ejs.j2c.ConnectionManager.allocateMCWrapper(ConnectionManager.java:547)
      at com
      .ibm.ejs.j2c.ConnectionManager.allocateConnection(ConnectionManager.java:283)
      at com
      .ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:143)
      at com
      .ibm.ws.rsadapter.jdbc.WSJdbcDataSource.getConnection(WSJdbcDataSource.java:116)
      at com
      .testt.auth.dao.AuditDao.store(AuditDao.java:37)
      at sun
      .reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun
      .reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:95)
      at sun
      .reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
      at java
      .lang.reflect.Method.invoke(Method.java:508)
      at org
      .jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:88)
      at org
      .jboss.weld.injection.StaticMethodInjectionPoint.invoke(StaticMethodInjectionPoint.java:78)
      at org
      .jboss.weld.injection.MethodInvocationStrategy$SimpleMethodInvocationStrategy.invoke(MethodInvocationStrategy.java:129)
      at org
      .jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:299)
      at org
      .jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:277)
      at org
      .jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:255)
      at org
      .jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:269)
      at org
      .jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:258)
      at org
      .jboss.weld.event.EventImpl.fire(EventImpl.java:91)
      at com
      .test.auth.AuthHomeServlet.audit(AuthHomeServlet.java:72)
      at com
      .test.auth.AuthHomeServlet.doPost(AuthHomeServlet.java:37)
      at javax
      .servlet.http.HttpServlet.service(HttpServlet.java:707)
      at javax
      .servlet.http.HttpServlet.service(HttpServlet.java:790)
      at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1255)
      at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:743)
      at com
      .ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:440)
      at com
      .ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:147)
      at com
      .ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:89)
      at com
      .test.auth.MkidUserPrincipalFilter.doFilter(MkidUserPrincipalFilter.java:38)
      at com
      .ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:201)
      at com
      .ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:86)
      at com
      .ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:995)
      at com
      .ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1124)
      at com
      .ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1004)
      at com
      .ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:76)
      at com
      .ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:926)
      at com
      .ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:279)
      at com
      .ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:957)
      at com
      .ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:357)
      at com
      .ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:316)
      at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:499)
      at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:433)
      at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:313)
      at com
      .ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:284)
      at com
      .ibm.ws.channel.ssl.internal.SSLConnectionLink.determineNextChannel(SSLConnectionLink.java:1029)
      at com
      .ibm.ws.channel.ssl.internal.SSLConnectionLink.readyInboundPostHandshake(SSLConnectionLink.java:695)
      at com
      .ibm.ws.channel.ssl.internal.SSLConnectionLink$MyHandshakeCompletedCallback.complete(SSLConnectionLink.java:383)
      at com
      .ibm.ws.channel.ssl.internal.SSLUtils.handleHandshake(SSLUtils.java:947)
      at com
      .ibm.ws.channel.ssl.internal.SSLHandshakeIOCallback.complete(SSLHandshakeIOCallback.java:85)
      at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:501)
      at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:571)
      at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:926)
      at com
      .ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1015)
      at java
      .util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
      at java
      .util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
      at java
      .lang.Thread.run(Thread.java:785) 

      The
      following table shows the events that have run during this request. 
      Duration      Operation 30018.682ms + websphere.servlet.service | auth | authHomeServlet

      Why the JBDC driver Proxy session close operation taking that much time, what timeout I can configure there ?

       

      Message was edited by: Srikanth Dyapa