pool.getConnection() is hanging infinitely if network connection is dropped.

[amitagarwal-dev]

process.platform : linux
process.version : v14.20.0  
process.arch : x64  
require('oracledb').versionString : 19.16.0.0.0  
require('oracledb').oracleClientVersionString : 5.5.0  
db version : 19c  

Issue:

1) pool.getConnection() is hanging infinitely if network connection is dropped. I need to call oracledb.createPool(option); in order to establish a pool connection again. There is no reconnect by default or an error from oracledb to handle this.

2) While getting DPI1080 error from connection.execute(), i don't know why my promise is not returning. In case of other error same code is working fine.

Steps i am following to recreate both the issues:

1) first issue:

• once i have a pool after that i am disconnecting my vpn and calling pool.getConnection() after 20 sec which never returns or throws an error.

2) second issue:

• once i have a pool after that i am disconnecting my vpn and calling connection.execute() followed by pool.getConnection() after 5 sec which throws an error (DPI-1080: connection was closed by ORA-3156) but my async function never returns even though i am throwing that error.

Code

Full code is here: https://github.com/amitagarwal-dev/oracledb-test.git

• Line 16 is hanging ( issue 1 )
• Line 44 is never returning in case of DPI1080 error only ( issue 2 );

1. const oracledb = require("oracledb");
2. oracledb.outFormat = oracledb.OUT_FORMAT_OBJECT;
3. oracledb.fetchAsString = [oracledb.CLOB, oracledb.DATE];
4. 
5. class OracleRepository {
6.   _pool;
7. 
8.   async getLocationDetails(bcccode){
9.      let query = "BEGIN GET_BR_FC_CBC_NAME(:bcccode,:cursor); END;";
10.         let bindParameters = {
11.             bcccode: bcccode,
12.             cursor: { dir: oracledb.BIND_OUT, type: oracledb.DB_TYPE_CURSOR },
13.         };
14.         let result;
15.         console.log("stats",this._pool.getStatistics())
16.         let connection = await this._getConnection();
17. 
18.         try {
19.             try {
20.                 console.log("excuting sp");
21.                 result = await connection.execute(query, bindParameters);
22.                 console.log("excuting sp done");
23. 
24.             } catch (err) {
25.                 console.log("error executing",err);
26.                 throw `unable to execute oracle query [Method: OracleRepository.getLocationDetails] [query: ${query}] [parameters: ${JSON.stringify(bindParameters)}]`;
27.             }
28. 
29.             let resultSet = result.outBinds.cursor;
30. 
31.             let queryData = await this.fetchRefCursorFromStream(resultSet);
32.             console.log("##################",queryData)
33.             try{
34.                 return queryData[0];
35.             }
36.             catch(err){
37.                 console.log("#@@@@@@@@@@@@@",err);
38. 
39.                 throw `unable to json parse the result [Method: OracleRepository.getLocationDetails] [query: ${query}] [parameters: ${JSON.stringify(bindParameters)}] [err : ${err}]`
40.             }
41.         } catch (err) {
42.             console.log("catch",err);
43. 
44.             throw err;
45.         } finally {
46.             // release connection !IMPORTANT
47.             await this._closeConnection(connection);
48.         }
49.     }
50.     
51.      async closePoolConnection() {
52.         await this._pool.close();
53.     }
54.      fetchRefCursorFromStream(resultSet) {
55.         return new Promise((resolve, reject) => {
56.             let result = [];
57.             let stream = resultSet.toQueryStream();
58.             stream.on("error", (err) => {
59.                 return reject(`Error While Opening a Query Stream [Method: OracleRepository.fetchRefCursorFromStream]`
60.                 );
61.             });
62.             stream.on("data", (data) => {
63.                 result.push(data);
64.             });
65.             stream.on("end", function () {
66.                 stream.destroy();
67.             });
68.             stream.on("close", function () {
69.                 return resolve(result);
70.             });
71.         });
72.     }
73.      async getPool(option) {
74.         this._pool = await oracledb.createPool(option);
75.     }
76.      async _closeConnection(connection) {
77.         try {
78.             if (connection !== undefined) {
79.                 await connection.close();
80.             }
81.         } catch (err) {
82.             console.log("unknown error at OracleRepository.closeConnection: ", err);
83.         }
84.     }
85.      async _getConnection() {
86.         try {
87.             //console.log("pool",this._pool, "status", this._pool.status);
88.             let connection = await this._pool?.getConnection();
89.             console.log("pool connection found");
90. 
91.             connection.callTimeout = 20000;
92.             return connection;
93.         } catch (err) {
94.             console.log("_getConnection error", err);
95.             throw  `unable to get database connection [Method: OracleRepository.getConnection]`;
96.         }
97.     }
98. }
99. 
100. function connect(database) {
101.    if (database.ISSID == 1) {
102.        let connectString = `(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=${database.HOST})(PORT=${database.PORT}))(CONNECT_DATA=(SID=${database.DATABASE})))`;
103.        return connectString;
104.    } else {
105.        let connectString = `(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=${database.HOST})(PORT=${database.PORT}))(CONNECT_DATA=(SERVICE_NAME=${database.DATABASE})))`;
106.        return connectString;
107.    }
108. }
109. 
110. let orarepo = new OracleRepository();
111. async function init(){
112. 
113.    let option ={
114.    user: 'base_fi_6',
115.    password: 'base_fi_6' ,
116.    connectString: connect({HOST: '10.10.30.130', PORT: 1521, DATABASE: 'orcl' }),
117.    poolMax: 1000, //The maximum number of connections to which a connection pool can grow.
118.    poolMin: 10, //The minimum number of connections which will be open.
119.    poolTimeout: 15, //The number of seconds after which idle connections (unused in the pool) are terminated.
120.    queueTimeout: 3000, //Number of milliseconds after which connection requests waiting in the connection request queue are terminated.
121.    enableStatistics: true,
122.    queueMax: 1000,
123.    poolAlias: "WORKFLOW",
124.    poolPingInterval : 10
125. };
126. 
127. await orarepo.getPool(option);
128. console.log("pool created");
129. await callSp();
130. }
131. 
132. init().catch(err =>{
133.    console.log("init error", err);
134. })
135. 
136. 
137. function pause(t){
138.    return new Promise(resolve =>{
139.        setTimeout(()=>{
140.            return resolve();
141.        },t)
142.    }); 
143. }
144. 
145. async function callSp(){
146.    try{
147.        console.log("calling sp")
148.        let result = await orarepo.getLocationDetails('123456');
149.        console.log("result", result);
150.        await pause(8000);
151.        return await callSp();
152.        
153.        } catch(e){
154.            console.log("sp error",e);
155.            throw e;
156.        }
157. }

[amitagarwal-dev]

@cjbj

[sharadraju]

Thanks for reporting this. We are currently looking into it.

Have you tried using the latest node-oracledb version (6.0.3) with Thin mode #1587

[amitagarwal-dev]

Yes, i tried 6.0.3 also.
Same issue is there

[amitagarwal-dev]

@sharadraju issue 1 is happening only when i am trying to connect db via a vpn, if i connect directly to my office network via a lan then it is reconnecting when network comes online.

[amitagarwal-dev]

if vpn connection drops then it is not reconnecting even through i reconnected again.

[amitagarwal-dev]

Do we have any timeout for getting connection from the pool? It will be better if i get some timeout error while getting connection from the pool, so that admin can check the connectivity.

[cjbj]

A network hang could be mitigated by https://node-oracledb.readthedocs.io/en/latest/user_guide/connection_handling.html#limiting-the-time-to-open-new-connections

If the pool is already at max size, then queueTimeout plays a role, see https://node-oracledb.readthedocs.io/en/latest/user_guide/connection_handling.html#connection-pool-queue

[sharadraju]

You also have the connectTimeout and transportConnectTimeout parameters introduced from node-oracledb 6.0 onwards available with the Thin mode. Please see https://node-oracledb.readthedocs.io/en/latest/api_manual/oracledb.html#createpoolpoolattrspooltimeout

[amitagarwal-dev]

@cjbj @sharadraju thanks for the reply!
let me go through the links. Also i have an update for issue 2.
Actually Line 47 is preventing it from returning from the function where i am throwing the error.
Because connection is already (DPI-1080: connection was closed by ORA-3156) closed, so my connection.close() is somewhere got stuck. let me see how to handle this.

Give me some time, after the implementation i will close the issue by myself.

[amitagarwal-dev]

connection.close() is getting stucked infinitely after (DPI-1080: connection was closed by ORA-3156).

[cjbj]

Did you happen try (though it is unlikely to have changed), 6.0 in Thick or Thin mode?

[amitagarwal-dev]

connection.close() is getting stucked infinitely after (DPI-1080: connection was closed by ORA-3156).

I tried this in 5.5.0

[amitagarwal-dev]

You also have the connectTimeout and transportConnectTimeout parameters introduced from node-oracledb 6.0 onwards available with the Thin mode. Please see https://node-oracledb.readthedocs.io/en/latest/api_manual/oracledb.html#createpoolpoolattrspooltimeout

@sharadraju i am changing connect string in 5.5.0, will it work? I added (CONNECT_TIMEOUT=40)

function connect(database) {
    if (database.ISSID == 1) {
        let connectString = `(DESCRIPTION=(CONNECT_TIMEOUT=40)(ADDRESS=(PROTOCOL=TCP)(HOST=${database.HOST})(PORT=${database.PORT}))(CONNECT_DATA=(SID=${database.DATABASE})))`;
        return connectString;
    } else {
        let connectString = `(DESCRIPTION=(CONNECT_TIMEOUT=40)(ADDRESS=(PROTOCOL=TCP)(HOST=${database.HOST})(PORT=${database.PORT}))(CONNECT_DATA=(SERVICE_NAME=${database.DATABASE})))`;
        return connectString;
    }
}

[sharadraju]

Yes CONNECT_TIMEOUT in the connect string should work.

[monita1208]

connection.close() is getting stucked infinitely after (DPI-1080: connection was closed by ORA-3156).

async closePoolConnection() {
  await this._pool.close();
}

Can you call method after connection close. Program will not terminate until pool is open.

[amitagarwal-dev]

@monita1208 i didn't get your point.

I am following the below flow in my application:

1. create a pool by calling oracledb.createPool(option).
2. get a connection from the pool by calling pool.getConnection().
3. execute a query by calling connection.execute().
4. close the connection by calling connection.close().
5. close the pool once shutting down the application.

So if network drop is there after step 2 then step 4 is hanging.

[sharadraju]

@monita1208 i didn't get your point.

I am following the below flow in my application:

1. create a pool by calling oracledb.createPool(option).
2. get a connection from the pool by calling pool.getConnection().
3. execute a query by calling connection.execute().
4. close the connection by calling connection.close().
5. close the pool once shutting down the application.

So if network drop is there after step 2 then step 4 is hanging.

@amitagarwal-dev , since the network drop is there in step 3, you might want to set connection.callTimeout() to an appropriate value. See callTimeout

[amitagarwal-dev]

@sharadraju step 3 already thrown an error i.e (DPI-1080: connection was closed by ORA-3156).
I guess callTimeout will be helpful when i am working with a valid connection but here error itself is saying connection was closed by ORA-3156.

[amitagarwal-dev]

Yes CONNECT_TIMEOUT in the connect string should work.

@sharadraju let me test

[sharadraju]

The reason to use callTimeout would be to throw the Timeout error and return control to the application before the DPI-1080 error is thrown. i.e., before the connection becomes invalid But, based on your test case, it seems you would want us to handle the DPI-1080 error and then let the application continue further.

We are trying to replicate your scenario internally, though. Please give us some time to get back on this.

CONNECT_TIMEOUT would only be applicable at the time of connection creation. Since the connection is already created in your case, this parameter may not be helpful.

[cjbj]

wait this._pool.close();

You almost definitely should pass a draintime argument here otherwise the pool may not close if connections are still in use. Check the doc and examples.

Regarding the pool sizing, is your Node.js process really capable of handling 1000 connections efficiently (it might be, but is it something to check)? Should you use a fixed pool (see the pool sizing doc)?

poolMax: 1000, poolMin: 10,

The timeout looks low and could lead to more DB instability if connections have to be recreated frequently:

poolTimeout: 15,

[amitagarwal-dev]

@sharadraju if you see line 91, i already tried callTimeout but no effect on the error and the issue.

[amitagarwal-dev]

wait this._pool.close();

You almost definitely should pass a draintime argument here otherwise the pool may not close if connections are still in use. Check the doc and examples.

Regarding the pool sizing, is your Node.js process really capable of handling 1000 connections efficiently (it might be, but is it something to check)? Should you use a fixed pool (see the pool sizing doc)?

poolMax: 1000, poolMin: 10,

The timeout looks low and could lead to more DB instability if connections have to be recreated frequently:

poolTimeout: 15,

@cjbj these are random values right now, my production configuration is different. I already did a load testing to tune these parameters. You helped me on this earlier (#1457 and #1465 ). Currently i am just using one connection.

[sudarshan12s]

We are trying to reproduce the issue . Can you set EXPIRE_TIME=1 and confirm the behaviour.

With 18c+ client libraries it can be added as (EXPIRE_TIME=n) to the DESCRIPTION section of a connect descriptor
With 19c+ client libraries it can be used via Easy Connect: host/service?expire_time=n.
With 21c client libraries it can be used in a client-side sqlnet.ora.

[monita1208]

Please update init() of shared program to include pool close. Due to poolMin = 10 and 1 connection close with DPI error, still 9 connections left in pool. Pool close call will terminate open connections.

async function init(){

    let option ={
    user: 'user',
    password: 'pwd' ,
    connectString: 'CS',
    poolMax: 1000, //The maximum number of connections to which a connection pool can grow.
    poolMin: 10, //The minimum number of connections which will be open.
    poolTimeout: 15, //The number of seconds after which idle connections (unused in the pool) are terminated.
    queueTimeout: 3000, //Number of milliseconds after which connection requests waiting in the connection request queue are terminated.
    enableStatistics: true,
    queueMax: 1000,
    poolAlias: "WORKFLOW",
    poolPingInterval : 10
  };

  try {
    await orarepo.getPool(option);
    console.log("pool created");
    await callSp();
  } catch(error) {
    console.log("init error", error);
  } finally {
    await orarepo.closePoolConnection();
  }
}

Can you also try below sample program. You can try with node driver version 6.0.3 and 5.5 (thick mode) 1) Pool creation done 2) A connection got created 3) Sleep for 10 sec started 4) Disconnect from VPN 5) 10 sec sleep time over 6) Execute a query. This will throw DPI-1080 7) Close connection Program doesn't go on infinite wait.

const oracledb = require('oracledb');
oracledb.initOracleClient({ libDir: 'Oracle client library location' });
function sleep(ms) {
  return new Promise((resolve) => {
    setTimeout(resolve, ms);
  });
}

async function run() {
  const config = {
  user: 'user',
  password: 'pwd',
  poolMin: 0,
  poolMax: 10,
  poolTimeout: 120,
  queueTimeout: 10000,
  enableStatistics: true,
  poolAlias: "10",
  connectString :  'CS',
};

  let pool = await oracledb.createPool(config);
  const conn1 =  await pool.getConnection();
  conn1.callTimeout = 1;
  console.log("sleep started, disconnect from VPN");
  await sleep(10000);
  console.log("n/w dropped and sleep over");
  console.log('waiting....')
  try {
    const res = await conn1.execute(`select 1 from dual`);
    console.log('res=' + JSON.stringify(res));
  } catch (error) {
    console.log(error);
  }
  await conn1.close();
  await pool.close(0);
}
run();

[sudarshan12s]

@amitagarwal-dev , For the hang, we are able to simulate it locally. Can you set the following in client sqlnet.ora file , run the client application and see if it resolves the hang and terminates gracefully.

SQLNET.RECV_TIMEOUT=5
SQLNET.EXPIRE_TIME=1

[amitagarwal-dev]

@monita1208 i tried your second code snippet, it is working fine but when i give poolmin=10 then again await conn1.close(); is hanging.
Also conn1.callTimeout = 1; is causing DPI-1080: connection was closed by ORA-3156 error in case of not stopping my vpn, may be because 1ms is too less for a round trip timeout, if i am increasing it to 1000ms then it is working fine.
So i guess callTimeout is coming into the picture when we have a valid connection. I tried with 5.5.0.

Do you have any idea for this:

when i give poolmin=10 then again `await conn1.close();` is hanging.  

[amitagarwal-dev]

@sudarshan12s i am not able to find sqlnet.ora file in my machine. Do you know the path? i tried with locate sqlnet.ora command but no lead.

[monita1208]

@amitagarwal-dev You can update callTimeout value as per your need. 1ms is low value and it is used here only for testing reported issue.

-- when i give poolmin=10 then again await conn1.close(); is hanging.
Program is going into irresponsive/hang state when we update sample program with poolMin 10. Solution is to update sqlnet.ora file with value : SQLNET.RECV_TIMEOUT=5 For more info on this parameter refer: https://docs.oracle.com/cd/E11882_01/network.112/e10835/sqlnet.htm#NETRF227

You can use echo $TNS_ADMIN to get location of sqlnet.ora file. "TNS_ADMIN is an environment variable that points to the directory where the SQL*Net configuration files (like sqlnet.ora and tnsnames.ora)".

[cjbj]

@amitagarwal-dev the node-oracledb doc explains where you can find an existing, or create a new, sqlnet.ora file. See the section Using Optional Oracle Configuration Files.

[amitagarwal-dev]

@monita1208 let me try and confirm.

[amitagarwal-dev]

@monita1208 below code is working fine with SQLNET.RECV_TIMEOUT=10, now await conn1.close() is not hanging infinitely but it is taking a lot of time in order to resolve the await. i guess it depends on the poolmin value. Below is the code and the log.

const oracledb = require('oracledb');
//oracledb.initOracleClient({ libDir: 'Oracle client library location' });
function sleep(ms) {
  return new Promise((resolve) => {
    setTimeout(resolve, ms);
  });
}
function connect(database) {
    if (database.ISSID == 1) {
        let connectString = `(DESCRIPTION=(CONNECT_TIMEOUT=40)(ADDRESS=(PROTOCOL=TCP)(HOST=${database.HOST})(PORT=${database.PORT}))(CONNECT_DATA=(SID=${database.DATABASE})))`;
        return connectString;
    } else {
        let connectString = `(DESCRIPTION=(CONNECT_TIMEOUT=40)(ADDRESS=(PROTOCOL=TCP)(HOST=${database.HOST})(PORT=${database.PORT}))(CONNECT_DATA=(SERVICE_NAME=${database.DATABASE})))`;
        return connectString;
    }
}
async function run() {

    let config ={
        user: 'base_fi_6',
        password: 'base_fi_6' ,
        connectString: connect({HOST: '10.10.30.130', PORT: 1521, DATABASE: 'orcl' }),
        poolMax: 100, //The maximum number of connections to which a connection pool can grow.
        poolMin: 10, //The minimum number of connections which will be open.
        poolTimeout: 15, //The number of seconds after which idle connections (unused in the pool) are terminated.
        queueTimeout: 3000, //Number of milliseconds after which connection requests waiting in the connection request queue are terminated.
        enableStatistics: true,
        queueMax: 1000,
        poolAlias: "WORKFLOW",
    };

  let pool = await oracledb.createPool(config);
  console.log("sleep started, disconnect from VPN",new Date());
  await sleep(20000);
  console.log("n/w dropped and sleep over",new Date());
  console.log('waiting for pool.getConnection() ....',new Date())
  const conn1 =  await pool.getConnection();
  conn1.callTimeout = 1000;
  console.log("sleep started, disconnect from VPN",new Date());
  await sleep(20000);
  console.log("n/w dropped and sleep over",new Date());
  console.log('waiting....',new Date())
  try {
    const res = await conn1.execute(`select 1 from dual`);
    console.log('res=' + JSON.stringify(res));
  } catch (error) {
    console.log(error,new Date());
  }
  console.log('doing conn1.close()',new Date());
  await conn1.close();
  console.log('doing pool.close(0)',new Date());
  await pool.close(0);
}
run().catch(error => {
    console.log("catch error: ",error);
});

• Logs with poolmin=10

1. sleep started, disconnect from VPN 2023-08-04T08:09:32.665Z
2. n/w dropped and sleep over 2023-08-04T08:09:52.687Z
3. waiting for pool.getConnection() .... 2023-08-04T08:09:52.687Z
4. sleep started, disconnect from VPN 2023-08-04T08:09:52.688Z
5. n/w dropped and sleep over 2023-08-04T08:10:12.706Z
6. waiting.... 2023-08-04T08:10:12.706Z
7. Error: DPI-1080: connection was closed by ORA-3156
8. at async run (/home/amitagarwal/Desktop/server/workflow/oracle-test/github.js:45:17) {
9. errorNum: 0,
10. offset: 0
11. } 2023-08-04T08:10:14.711Z
12. doing conn1.close() 2023-08-04T08:10:14.712Z
13. doing pool.close(0) 2023-08-04T08:13:18.808Z

* Logs with poolmin=2  

1. sleep started, disconnect from VPN 2023-08-04T08:15:11.588Z
2. n/w dropped and sleep over 2023-08-04T08:15:31.605Z
3. waiting for pool.getConnection() .... 2023-08-04T08:15:31.606Z
4. sleep started, disconnect from VPN 2023-08-04T08:15:31.607Z
5. n/w dropped and sleep over 2023-08-04T08:15:51.626Z
6. waiting.... 2023-08-04T08:15:51.626Z
7. Error: DPI-1080: connection was closed by ORA-3156
8. at async run (/home/amitagarwal/Desktop/server/workflow/oracle-test/github.js:45:17) {
9. errorNum: 0,
10. offset: 0
11. } 2023-08-04T08:15:53.631Z
12. doing conn1.close() 2023-08-04T08:15:53.632Z
13. doing pool.close(0) 2023-08-04T08:16:13.912Z

`NOTE: I stopped my vpn just after line 1`.  

### Points to check:  

* See the time difference between line 12 and 13 in both the cases.  

[monita1208]

@amitagarwal-dev You can check if time taken for conn1 closure is consistent with multiple attempts, when poolMin is 10 and poolMin is 2. When you are closing conn1 using await conn1.close();, it is going to close single connection only. At time of pool close, remaining connections will be taken care. At pool closure, if poolMin is 10 then it will take more time as compared to poolMin 2.

[amitagarwal-dev]

@monita1208 whatever logs I shared in which I am closing the current connection only, so it should take even time. When I will close pool then only poolmin should come into the picture.

[amitagarwal-dev]

@monita1208 can you simulate the same?

[amitagarwal-dev]

any update?

[monita1208]

@amitagarwal-dev You can always check the open and in-use count of connections using the pool parameters pool.connectionsOpen and pool.connectionsInUse. Before closing the connection parameter results are- pool.connectionsOpen = (poolMin value) 10 pool.connectionsInUse = 1 After closing the connection parameter results are- pool.connectionsOpen = 0 pool.connectionsInUse = 0

Due to the network issue, the connection which we were trying to close is already closed resulting in a check and closure of the remaining connections in the pool. Thus, you were getting ~3mins time in closing a connection with poolMin as 10 and ~30sec time in closing a connection with poolMin as 2.

In case of no network issues and at the time of connection closure, only a single connection will be closed and the closure of the remaining connections happens at the time of pool close.

[amitagarwal-dev]

@monita1208 is this the expected behaviour or its a bug?

[monita1208]

@amitagarwal-dev This is expected behaviour.

[amitagarwal-dev]

@monita1208 don't you think that conn1.close() should operate on that connection only? Instead of closing all the connection in the pool, I guess pool should close the other invalid connection if it is not taken.
In a production environment, open connection will be more. Awaiting for close() will take a lot of time.

[monita1208]

@amitagarwal-dev This is pool feature of clearing bad connections from pool.

[amitagarwal-dev]

ok thanks for helping @monita1208 @sudarshan12s @cjbj

[sharadraju]

@amitagarwal-dev The pool check in the case of an invalid connection has been the behavior for all of our Oracle Database drivers now. We do not want a pool of invalid connections to remain open, once the network has gone bad. What you are requesting is a behavior change, across all the drivers.

We will however evaluate it internally and see if we can provide an option of closing a single bad connection from a pool (without the pool check), in case of a network outage in a future release.

[amitagarwal-dev]

@sharadraju I don't know whether its a problem or not but whoever is taking the connection from the pool is closing the connection using conn.close(), so close() scope should remain to that connection only. Why close() is interfering with the other connection?