Node-oracledb: v4.0.0: Timeout when creating pool

[brano543]

Hello,

I am using Node.js v10.16.0 and latest node-oracledb v4.0.0. However while trying to create pool the standard way I am getting timeout. Same code works with 3.1.2. I am using tnsnames.ora way to connect.

module.exports = async function connectToDatabases(fastify) {
    const options = {
        pool: {
            user: process.env.ORACLE_USERNAME,
            password: process.env.ORACLE_PASSWORD,
            connectString: 'DB',
            poolMin: 4,
            poolMax: 4,
            poolIncrement: 0,
            poolTimeout: 60
        },
        fetchAsString: [oracledb.DATE]
    };

    // fetch date as string
    oracledb.fetchAsString = options.fetchAsString;

    // create pool
    const pool = await oracledb.createPool(options.pool);

    const oracle = {
        getConnection: pool.getConnection.bind(pool),
        pool,
        db: oracledb
    };

 fastify.decorate('oracle', () => {
        return oracle;
    });
}

[anthony-tuininga]

Can you provide the platform and the error you are receiving along with the traceback? Do you get the same issue with the examples that are provided with node-oracledb?

[brano543]

I was able to identify the root cause of the problem. It is not related to code at all. Given below code If I am trying to access by using easy connect string it works as long as I don't define TNS_ADMIN variable.

Platform: Linux (Red Hat Enterprise Linux Server release 7.6 (Maipo))

Steps to replicate:

Tnsnames.ora (which works with 3.1.2 node-oracledb)

DB=
(DESCRIPTION=
    (ADDRESS_LIST=
        (ADDRESS=
            (PROTOCOL=tcp)
            (HOST=my_hostname)
            (PORT=1529)
        )
    )
    (CONNECT_DATA=
        (SERVER=DEDICATED)
        (SERVICE_NAME=my_service_name)
    )
) 

Sample code

const oracledb = require('oracledb');

async function init() {
    try {
        // Create a connection pool which will later be accessed via the
        // pool cache as the 'default' pool.
        await oracledb.createPool({
           user: process.env.ORACLE_USERNAME,
           password: process.env.ORACLE_PASSWORD,
            connectString: 'host_name:1529/service_name'
        });
        console.log('Connection pool started');

        // Now the pool is running, it can be used
        await dostuff();
    } catch (err) {
        console.log(`init() error: ${err.message}`);
    } finally {
        await closePoolAndExit();
    }
}

async function dostuff() {
    let connection;
    try {
        // Get a connection from the default pool
        connection = await oracledb.getConnection();
        const sql = `SELECT sysdate FROM dual WHERE :b = 1`;
        const binds = [1];
        const options = { outFormat: oracledb.OUT_FORMAT_OBJECT };
        const result = await connection.execute(sql, binds, options);
        console.log(result);
    } catch (err) {
        console.log(`dostuff() error: ${err}`);
    } finally {
        if (connection) {
            try {
                // Put the connection back in the pool
                await connection.close();
            } catch (err) {
                console.log(`connection close error: ${err}`);
            }
        }
    }
}

async function closePoolAndExit() {
    console.log('\nTerminating');
    try {
        // Get the pool from the pool cache and close it when no
        // connections are in use, or force it closed after 10 seconds
        // If this hangs, you may need DISABLE_OOB=ON in a sqlnet.ora file
        await oracledb.getPool().close(10);
        console.log('Pool closed');
        process.exit(0);
    } catch (err) {
        console.log(`error closePoolAndExit() ${err.message}`);
        process.exit(1);
    }
}

process.once('SIGTERM', closePoolAndExit).once('SIGINT', closePoolAndExit);

init();

Output

$ export TNS_ADMIN=
$ node connectionpool.js 
Connection pool started
{ metaData: [ { name: 'SYSDATE' } ],
  rows: [ { SYSDATE: 2019-07-25T13:24:06.000Z } ] }

Terminating
Pool closed

However if I define TNS_ADMIN pointing to tnsnames.ora, I get this behaviour:

Connection pool started
subscriber 1 create failed: timedout
{ metaData: [ { name: 'SYSDATE' } ],
  rows: [ { SYSDATE: 2019-07-25T13:26:30.000Z } ] }

Terminating
Pool closed

It is not exactly throwing error and the example continues to finish.

[anthony-tuininga]

Just for interest, can you add to the beginning of your code this code snippet?

oracledb.events = false;

The default value has changed from 3.1 to 4.0 and it would be worth knowing if this is a side effect of that change. Thanks!

[brano543]

This magic line fixes the problem in both codes. What does this events flag change?

[anthony-tuininga]

The documentation should answer your question, I think! Its good to know this is the source of your issue. I'll see what @cjbj wants to do, whether the change needs to be highlighted a bit more in the change log or the documentation adjusted further.

[brano543]

I have read the documentation,but I still don't understand the cause of issue. This should just enable additional subscribe method, so why does it break the successful creation of the pool? Or does this flag require something special to be set up in Oracle DB to work properly? We are using this version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production.

[anthony-tuininga]

I don't know the cause of the issue either, but we can ask internally and get back to you. As noted in the documentation, though, this sets up notification for various events (including high availability events). I suspect that some sort of network configuration is causing the problems -- but hopefully someone with more knowledge in this area can answer your question. In the meantime, though, you have a workaround!

[brano543]

Thank you, Anthony ! It would be great to know, maybe our DBA's would be able to set it up the way we would be able to benefit from these new features.

[cjbj]

@brano543 annoying for us all; we'll have to have a quick review when our session pool experts are next online.

But it would be helpful to know a cause before we jump. Do you have any sqlnet.ora parameters set? Can your DBA shed any light on how the DB service was configured?

One semi-random thing to try is to keep the (new) default events=true mode and try a sqlnet.ora with DISABLE_OOB=ON

[brano543]

@cjbj I already had that option there.

My sqlnet.ora

DIAG_SIGHANDLER_ENABLED=FALSE
DIAG_ADR_ENABLED=OFF
DIAG_DDE_ENABLED=FALSE
SQLNET.RECV_TIMEOUT=3600
DISABLE_OOB=ON

I have investigated and we are not using RAC, it is just a single node instance. Can it be issue?

[cjbj]

@brano543 can you find out how the DB service was configured? Anything special?

More interestingly, development folk want to know the actual Oracle error.

[brano543]

Could you be more specific? Are there some SQL commands which can let you know this? I don't have access to SYSDBA account, so most likely I won't be able to figure it out, but I can try.

Node-oracledb returns only "subscriber 1 create failed: timedout". I don't know where should I look for error.

[anthony-tuininga]

Did you search your own code for that message?

Can you also post the contents of your $TNS_ADMIN directory since you are saying the error message only appears when you set that environment variable?

[mcclenney]

I've just upgraded to v4, and my createPool call takes about 10 seconds when oracledb.events = true vs about 1 second when oracledb.events = false. Is this to be expected?

[cjbj]

@mcclenney can you tell us how the DB service was configured? Is it configured to send FAN events?

What are the pool parameters - I assume you have the same settings in both scenarios?

[cjbj]

@mcclenney Can you set a couple of trace parameters and collect a log file for me? Send me email (see my profile) and we can take it offline.

[mcclenney]

@cjbj I'm not sure if it's configured to send FAN events. I don't have access to ssh into the instance. I'll have to check with my db admin. Here's my pool parameters when creating pool (same in both scenarios):

"poolMin": 1,
"poolMax": 10,
"poolTimeout": 60,
"poolincrement": 1,
"queueRequests": true,
"queueTimeout": 60,
"maxRows": 100

I'll see if I can collect some more log info.

Edit: I tried setting SQL_TRACE=true, but I have insufficient privileges. So, I don't have log file. 😞

[cjbj]

@mcclenney the traces I was wondering about are from setting these two env vars before starting the app.
ORACLE_ONS_DEBUG when set (to any value) the ONS client debug is enabled.
ORACLE_ONS_LOGFILE set to a file name (the directory for the file must already exist).

You could email me the traces, depending what you want to share on GH. Or use a gist.

What are you DB and Oracle client versions?

[PeterMerkert]

Hi there,

I have the same issue, that toggling oracledb.events = false results in a way faster startup. I have an ATP (18c) running in the Oracle Cloud.

I have added the two env vars ORACLE_ONS_DEBUG and ORACLE_ONS_LOGFILE.

Here the gist with the flag oracledb.events = true: https://gist.github.com/PeterMerkert/fbd498527dd6e5c9ac61fde26919b4ea
Here the log output from my application (first and last line of gist)

[1569303502826] INFO  (4137 on cryptomeerkat): [OracleDB] Connection pool in creation
[1569303583743] INFO  (4137 on cryptomeerkat): [OracleDB] Connection pool created

Startup time: 1 minutes 21 seconds. (oracledb.events = true)

There is no output when setting oracledb.events = false, but here are the timestamps on startup:

[1569303690353] INFO  (4137 on cryptomeerkat): [OracleDB] Connection pool in creation
[1569303695971] INFO  (4137 on cryptomeerkat): [OracleDB] Connection pool created

Startup time: 5 seconds. (oracledb.events = false)

And to make my setup more clear:

I set TNS_ADMIN=./wallet before application startup. We are having only the cwallet.sso and sqlnet.ora file in our project. It's sufficient to connect to the ATP apparently. The contents of the sqlnet.ora are also depicted in the image.

And the long timeout really just occurs with a remote ATP. For development purposes I connect to a local dockerized Oracle 18c and the pool creation is done in

[1569304364235] INFO  (4234 on cryptomeerkat): [OracleDB] Connection pool in creation
[1569304364553] INFO  (4234 on cryptomeerkat): [OracleDB] Connection pool created

Startup time: < 1 second. (oracledb.events = true, but local docker Oracle 18c)

[cjbj]

@PeterMerkert thanks for the detailed info. We'll review it with the ONS team. @dmcghan also saw this on ATP. I suspect we'll revert the events mode default back to false.

[cjbj]

node-oracledb 4.1 will revert events back to false so this shouldn't happen in out-of-the-box usage.