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
Is it related to DNS issue? Can anyone point me to right direction...
UPDATE
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
After switching to Oracle UCP, this issue disappeared as it has timeout on connection validation (15 sec). I posted this issue on Openliberty github, hope it will be fixed in future releases.