Autosys WebUI won't connect to the database after upgrade, java.sql.SQLRecoverableException: IO Error: The Network Adapter could not establish the connection, : java.io.IOException: Socket read timed out,

Products

• CA Workload Automation AE

Issue/Introduction

INFO   | jvm 1    | 2022/04/27 19:51:15 |        4 | Apr 27, 2022 7:51:14 PM com.ca.wcc.dbresource.datasource.UnlockingDatasource setParameters
INFO   | jvm 1    | 2022/04/27 19:51:15 |        4 | INFO: URL= jdbc:oracle:thin:@AUTOSYS_WCC, Driver= oracle.jdbc.driver.OracleDriver
INFO   | jvm 1    | 2022/04/27 19:51:15 |        4 | Apr 27, 2022 7:51:14 PM com.ca.wcc.dbresource.datasource.WccDataSource registerMBean
INFO   | jvm 1    | 2022/04/27 19:51:15 |        4 | INFO: Trying to create connection pool, retry attempt - 1
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 | Apr 27, 2022 7:51:17 PM org.apache.tomcat.jdbc.pool.ConnectionPool init
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 | SEVERE: Unable to create initial connections of pool.
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 | java.sql.SQLRecoverableException: IO Error: The Network Adapter could not establish the connection
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:774)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:688)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:39)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:691)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:347)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:228)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:769)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:697)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.ConnectionPool.init(ConnectionPool.java:496)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.ConnectionPool.<init>(ConnectionPool.java:154)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.DataSourceProxy.pCreatePool(DataSourceProxy.java:121)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.tomcat.jdbc.pool.DataSourceProxy.createPool(DataSourceProxy.java:110)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at com.ca.wcc.dbresource.datasource.WccDataSource.registerMBean(Unknown Source)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at com.ca.wcc.dbresource.datasource.UnlockingDatasource.setParameters(Unknown Source)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at com.ca.wcc.dbresource.datasource.WccDataSource.setPrefix(Unknown Source)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at java.lang.reflect.Method.invoke(Method.java:498)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.factory.BeanFactory.getObjectInstance(BeanFactory.java:264)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.factory.FactoryBase.getObjectInstance(FactoryBase.java:96)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at javax.naming.spi.NamingManager.getObjectInstance(NamingManager.java:332)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.NamingContext.lookup(NamingContext.java:864)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.NamingContext.lookup(NamingContext.java:158)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.NamingContextBindingsEnumeration.nextElementInternal(NamingContextBindingsEnumeration.java:115)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:69)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:32)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:133)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:140)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:107)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.lifecycleEvent(GlobalResourcesLifecycleListener.java:82)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:920)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.startup.Catalina.start(Catalina.java:772)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at java.lang.reflect.Method.invoke(Method.java:498)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:345)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:476)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at java.lang.reflect.Method.invoke(Method.java:498)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:429)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at java.lang.Thread.run(Thread.java:827)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 | Caused by: oracle.net.ns.NetException: The Network Adapter could not establish the connection
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:523)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.resolver.AddrResolution.resolveAndExecute(AddrResolution.java:521)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.ns.NSProtocol.establishConnection(NSProtocol.java:660)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.ns.NSProtocol.establishConnection(NSProtocol.java:639)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:189)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.ns.NSProtocol.connect(NSProtocol.java:317)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1438)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:518)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    ... 48 more
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 | Caused by: java.io.IOException: Socket read timed out, socket connect lapse 4 ms. /10.10.11.12 1521 3 1 true
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.TcpNTAdapter.connect(TcpNTAdapter.java:209)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.ConnOption.connect(ConnOption.java:161)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:470)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    ... 55 more
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 | Caused by: java.io.InterruptedIOException: Socket read timed out
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.TimeoutSocketChannel.handleInterrupt(TimeoutSocketChannel.java:307)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.TimeoutSocketChannel.<init>(TimeoutSocketChannel.java:84)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    at oracle.net.nt.TcpNTAdapter.connect(TcpNTAdapter.java:169)
INFO   | jvm 1    | 2022/04/27 19:51:17 |        6 |    ... 57 more

Cause

Customer's database was a load balanced configuration. Somehow the TRANSPORT_CONNECT_TIMEOUT of 3 seconds was not enough 

 

AUTOSYS_WCC =
  (DESCRIPTION = (CONNECT_TIMEOUT=90)(RETRY_COUNT=20)(RETRY_DELAY=3)(TRANSPORT_CONNECT_TIMEOUT=3)
    (ADDRESS_LIST =
      (LOAD_BALANCE = ON)
      (ADDRESS = (PROTOCOL = TCP)(HOST = dbnode1.company.com)(PORT = 1521))
      (ADDRESS = (PROTOCOL = TCP)(HOST = dbnode2.company.com)(PORT = 1521))
      (ADDRESS = (PROTOCOL = TCP)(HOST = dbnode3.company.com)(PORT = 1521))
      (ADDRESS = (PROTOCOL = TCP)(HOST = dbnode4.company.com)(PORT = 1521))
      (ADDRESS = (PROTOCOL = TCP)(HOST = dbnode5.company.com)(PORT = 1521))
      (ADDRESS = (PROTOCOL = TCP)(HOST = dbnode6.company.com)(PORT = 1521))
    )
    (CONNECT_DATA =
      (SERVER = dedicated)
      (SERVICE_NAME = AUTOSYS_WCC)
    )
 )

 

 

We did a tnsping AUTOSYS_WCC  repeatedly.  On some occasions it showed as taking >3 seconds

Environment

Release : 12.0

Component :

Resolution

Increased the TRANSPORT_CONNECT_TIMEOUT=30    and restarted WCC. It connected to the database fine and started working normally