TDM: Portal fails to "get connection pool" properties: |SEVERE: Unable to create initial connections of pool.

book

Article ID: 221910

calendar_today

Updated On:

Products

CA Test Data Manager (Data Finder / Grid Tools)

Issue/Introduction

 

After making updates to application properties, the CA TDM portal fails to start masking jobs.

In the back-end in the startup.log this is the entry I see:
FINEST|65900/0|21-08-17 09:36:42|Aug 17, 2021 9:36:42 AM org.apache.tomcat.jdbc.pool.ConnectionPool init
FINEST|65900/0|21-08-17 09:36:42|SEVERE: Unable to create initial connections of pool.
FINEST|65900/0|21-08-17 09:36:42|java.sql.SQLRecoverableException: Listener refused the connection with the following error:
FINEST|65900/0|21-08-17 09:36:42|ORA-12514, TNS:listener does not currently know of service requested in connect descriptor
FINEST|65900/0|21-08-17 09:36:42| 
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:854)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:793)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:57)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:747)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:562)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:319)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:212)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:744)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:676)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.init(ConnectionPool.java:483)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.<init>(ConnectionPool.java:154)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.DataSourceProxy.pCreatePool(DataSourceProxy.java:118)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.DataSourceProxy.createPool(DataSourceProxy.java:107)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:131)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:151)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:324)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DBConnectionUtils.validateConnection(DBConnectionUtils.java:30)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourcePool.createAndGetDataSource(DataSourcePool.java:80)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourcePool.getDataSource(DataSourcePool.java:98)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourceService.getProfileDataSource(DataSourceService.java:53)
FINEST|65900/0|21-08-17 09:36:42| at java.util.Optional.map(Optional.java:215)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourceService.getProfileDataSource(DataSourceService.java:44)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasync.scheduler.DatabaseProvider.getDataSource(DatabaseProvider.java:45)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasync.scheduler.SyncTask.run(SyncTask.java:67)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
FINEST|65900/0|21-08-17 09:36:42| at java.lang.Thread.run(Thread.java:748)
FINEST|65900/0|21-08-17 09:36:42|Caused by: oracle.net.ns.NetException: Listener refused the connection with the following error:
FINEST|65900/0|21-08-17 09:36:42|ORA-12514, TNS:listener does not currently know of service requested in connect descriptor
FINEST|65900/0|21-08-17 09:36:42| 
FINEST|65900/0|21-08-17 09:36:42| at oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:284)
FINEST|65900/0|21-08-17 09:36:42| at oracle.net.ns.NSProtocol.connect(NSProtocol.java:340)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1596)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:588)
FINEST|65900/0|21-08-17 09:36:42| ... 32 more
FINEST|65900/0|21-08-17 09:36:42|
FINEST|65900/0|21-08-17 09:36:42|Aug 17, 2021 9:36:42 AM org.apache.tomcat.jdbc.pool.ConnectionPool init
FINEST|65900/0|21-08-17 09:36:42|SEVERE: Unable to create initial connections of pool.
FINEST|65900/0|21-08-17 09:36:42|java.sql.SQLRecoverableException: IO Error: Got minus one from a read call
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:854)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:793)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:57)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:747)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:562)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:319)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:212)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:744)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:676)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.init(ConnectionPool.java:483)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.ConnectionPool.<init>(ConnectionPool.java:154)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.DataSourceProxy.pCreatePool(DataSourceProxy.java:118)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.DataSourceProxy.createPool(DataSourceProxy.java:107)
FINEST|65900/0|21-08-17 09:36:42| at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:131)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:151)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78)
FINEST|65900/0|21-08-17 09:36:42| at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:324)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DBConnectionUtils.validateConnection(DBConnectionUtils.java:30)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourcePool.createAndGetDataSource(DataSourcePool.java:80)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourcePool.getDataSource(DataSourcePool.java:98)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourceService.getProfileDataSource(DataSourceService.java:53)
FINEST|65900/0|21-08-17 09:36:42| at java.util.Optional.map(Optional.java:215)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasource.DataSourceService.getProfileDataSource(DataSourceService.java:44)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasync.scheduler.DatabaseProvider.getDataSource(DatabaseProvider.java:45)
FINEST|65900/0|21-08-17 09:36:42| at com.ca.tdm.findreserve.datasync.scheduler.SyncTask.run(SyncTask.java:67)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
FINEST|65900/0|21-08-17 09:36:42| at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
FINEST|65900/0|21-08-17 09:36:42| at java.lang.Thread.run(Thread.java:748)
FINEST|65900/0|21-08-17 09:36:42|Caused by: oracle.net.ns.NetException: Got minus one from a read call
FINEST|65900/0|21-08-17 09:36:42| at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:557)
FINEST|65900/0|21-08-17 09:36:42| at oracle.net.ns.NIOPacket.readNIOPacket(NIOPacket.java:403)
FINEST|65900/0|21-08-17 09:36:42| at oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:127)
FINEST|65900/0|21-08-17 09:36:42| at oracle.net.ns.NSProtocol.connect(NSProtocol.java:340)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1596)
FINEST|65900/0|21-08-17 09:36:42| at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:588)
FINEST|65900/0|21-08-17 09:36:42| ... 32 more

Why is the masking job failing and how do we correct it?

Cause

 

The target database was an Oracle database and the Oracle TNS Listener was down.

Environment

 

TDM 4.9.1

Component: TDM Web Portal

Resolution

 
 

There were was a problem with the target Oracle database.
The Local DBA had to correct the issue.

 

Additional Information

 

In the Start-up logs we can see the following error:


FINEST|65900/0|21-08-17 09:36:42|Caused by: oracle.net.ns.NetException: Listener refused the connection with the following error:
FINEST|65900/0|21-08-17 09:36:42|ORA-12514, TNS:listener does not currently know of service requested in connect descriptor

from the masking log

2021-08-17 14:31:03.425 UTC [INFO ] [FdmProgressNotifier      ] --- [U:][M:][P:]                     c.c.t.f.s.FdmProgressNotifier:  collectMetrics: fdm#: 0 overall jobState: FAILED allStopped: true failed: true
2021-08-17 14:31:03.425 UTC [INFO ] [FdmProgressNotifier      ] --- [U:][M:][P:]                     c.c.t.f.s.FdmProgressNotifier:  collectMetrics: overall job progress: {"msgType":"JOB_PROGRESS","text":"","jobId":1424,"jobState":"RUNNING","restartOptionEnabled":null,"counters":{"TABLE_METRICS":"{}","startTime":"1629210661394","endTime":"1629210663410","totalRows":"0","stopDate":"1629210663410","rowsMasked":"0","errors":"(1) <HOSTNAME.DOMAIN.COM>.SOT01: Connection error: java.sql.SQLRecoverableException: IO Error: Got minus one from a read call, Error connecting with connection parameters "}}
2021-08-17 14:31:03.425 UTC [INFO ] [FdmProgressNotifier      ] --- [U:][M:][P:]                     c.c.t.f.s.FdmProgressNotifier:  run: job: 1424:  Sent final notification: state: RUNNING errors: (1) <HOSTNAME.DOMAIN.COM>.SOT01: Connection error: java.sql.SQLRecoverableException: IO Error: Got minus one from a read call, Error connecting with connection parameters 
2021-08-17 14:31:03.425 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  logFDMOutputs: copying fdm console outputs to masking log...
2021-08-17 14:31:03.425 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  logFDMOutputs: -------------------------------------------------------------------------------
2021-08-17 14:31:03.425 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  logFDMOutputs: fdm#: 0 schema: <HOSTNAME.DOMAIN.COM>.SOT01 csv: fdm_mask_SOT01_<HOSTNAME.DOMAIN.COM>_SOT01_SOT01.csv
2021-08-17 14:31:03.425 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  logFDMOutputs: -------------------------------------------------------------------------------
2021-08-17 14:31:03.425 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.285 Fastdatamasker version: 4.9.177.0 
2021-08-17 14:31:03.425 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.300 Fastdatamasker build date - July 5 2021 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.332 PID:[email protected]<HOSTNAME.DOMAIN.COM>
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.332 Java version 1.8.0_292 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.332 OPERATING SYSTEM USER: <HOSTNAME.DOMAIN.COM>$ 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.332 Skipping cloakware configuration 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.347 attempting to connect 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.347 Using URL:jdbc:oracle:thin:@//<HOSTNAME.DOMAIN.COM>:1525/OPSLHD 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.597 Connecting with driver: oracle.jdbc.driver.OracleDriver using URL: jdbc:oracle:thin:@//<HOSTNAME.DOMAIN.COM>:1525/OPSLHD 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.863 Database service has not started 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.863 or supplied connection parameters are incorrect: connection_SOT01_<HOSTNAME.DOMAIN.COM>_SOT01_SOT01.txt 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.879 close: closing down. Final job state: FAILED 
2021-08-17 14:31:03.441 UTC [INFO ] [SimpleAsyncTaskExecutor-2] --- [U:][M:][P:]                      c.c.t.f.s.CallFastDataMasker:  #0: 2021-08-17 09:31:02.879 run: FDM progress thread:  Sending final notification: state: FAILED