NodeJS SDK Cluster.openbucket Takes 58 Seconds to Open a Connection

I am using NodeJS SDK. In the basic sample that follows I am opening a bucket to insert a single record. I have put each method in a promise to force them run one after another (sequentially) so I can measure each method’s running time.

My OS: Ubuntu 16.04

    'use strict';

    const couchbase = require('couchbase');
    const cluster = new couchbase.Cluster('couchbase://localhost');
    const uuid = require('uuid/v4');

    console.time('auth');
    cluster.authenticate('administrator', 'adminadmin');
    console.timeEnd('auth');

    function open() {
        return new Promise((resolve, reject) => {
            console.time('open');
            let bucket = cluster.openBucket('test', function (err) {
                if (err) {
                    console.error(err);
                    reject(err);
                }            
                resolve(bucket);
            });
        });
    }

    function insert(bucket, obj) {
        return new Promise((resolve, reject) => {
            console.time('upsert');
            bucket.upsert(`uuid::${blog.name}`, blog, function (err, result) {            
                if (err) {
                    console.log(err);
                    reject(err);                
                }
                resolve(bucket);
            });
        });
    }

    function dc(bucket) {    // disconnect
        return new Promise((resolve, reject) => {       
            console.time('dc');
            bucket.disconnect();
            resolve('ok');
        });
    }

    // data to insert
    let blog = {
        id: uuid(),
        name: 'Blog A',
        posts: [
            {
                id: uuid(),
                title: 'Post 1',
                content: 'lorem ipsum'
            }
        ]
    };

    open().then((bucket) => {
        console.timeEnd('open');    
        insert(bucket, blog).then((bucket) => {        
            console.timeEnd('upsert');        
            dc(bucket).then((res) => {            
                console.timeEnd('dc');
                console.log(res);
            });
        });
    });

The output is:

auth: 0.237ms
open: 58117.771ms <--- this shows the problem
upsert: 57.006ms
dc: 0.149ms
ok

I ran sdk-doctor. It gave me two lines worth mentioning:

  1. “WARN :arrow_forward: Your connection string specifies only a single host. You should consider adding additional static nodes from your cluster to this list to improve your applications fault-tolerance”
  2. “INFO :arrow_forward: Failed to retreive cluster information (status code: 401)”

and the summary is:

Summary:
[WARN] Your connection string specifies only a single host. You should consider adding additional static nodes from your cluster to this list to improve your applications fault-tolerance

Would anyone please help?

Could you please run your sample with LCB_LOGLEVEL=5 environment variable, and post the log here?

auth: 0.165ms
0ms [I0] {5832} [INFO] (instance - L:420) Version=2.7.5-njs, Changeset=09a9e28dfaf9f70a7e230de66909fc5d9f3a6b4f
0ms [I0] {5832} [INFO] (instance - L:421) Effective connection string: couchbase://localhost/test?enable_errmap=true&client_string=couchnode%2F2.4.2. Bucket=test
0ms [I0] {5832} [DEBUG] (instance - L:282) Applying initial cntl enable_errmap=true
0ms [I0] {5832} [DEBUG] (instance - L:282) Applying initial cntl client_string=couchnode/2.4.2
0ms [I0] {5832} [INFO] (instance - L:135) DNS SRV lookup failed: The requested feature is not supported by the client, either because of settings in the configured instance, or because of options disabled at the time the library was compiled. Ignore this if not relying on DNS SRV records
0ms [I0] {5832} [DEBUG] (instance - L:77) Adding host localhost:8091 to initial HTTP bootstrap list
0ms [I0] {5832} [DEBUG] (instance - L:77) Adding host localhost:11210 to initial CCCP bootstrap list
58057ms [I0] {5832} [DEBUG] (confmon - L:85) Preparing providers (this may be called multiple times)
58057ms [I0] {5832} [DEBUG] (confmon - L:92) Provider CCCP is ENABLED
58057ms [I0] {5832} [DEBUG] (confmon - L:92) Provider HTTP is ENABLED
58068ms [I0] {5832} [TRACE] (confmon - L:272) Refreshing current cluster map
58068ms [I0] {5832} [TRACE] (confmon - L:259) Attempting to retrieve cluster map via CCCP
58068ms [I0] {5832} [INFO] (cccp - L:149) Requesting connection to node localhost:11210 for CCCP configuration
58068ms [I0] {5832} [DEBUG] (lcbio_mgr - L:413) <localhost:11210> (HE=0x2a30b00) Creating new connection because none are available in the pool
58068ms [I0] {5832} [TRACE] (lcbio_mgr - L:328) <localhost:11210> (HE=0x2a30b00) New pool entry: I=0x2a54920
58068ms [I0] {5832} [INFO] (connection - L:465) <localhost:11210> (SOCK=0x2a46480) Starting. Timeout=2000000us
58077ms [I0] {5832} [TRACE] (connection - L:360) <localhost:11210> (SOCK=0x2a46480) Received completion handler. Status=0. errno=0
58080ms [I0] {5832} [INFO] (connection - L:139) <localhost:11210> (SOCK=0x2a46480) Connected established
58080ms [I0] {5832} [INFO] (lcbio - L:112) Translating errno=0, lcb=0x2d to NETWORK_ERROR
58080ms [I0] {5832} [INFO] (connection - L:100) <localhost:11210> (SOCK=0x2a46480) Couldn't set TCP_NODELAY
58080ms [I0] {5832} [DEBUG] (connection - L:98) <localhost:11210> (SOCK=0x2a46480) Successfully set TCP_KEEPALIVE
58080ms [I0] {5832} [DEBUG] (lcbio_mgr - L:287) <localhost:11210> (HE=0x2a30b00) Received result for I=0x2a54920,C=(nil); E=0x0
58080ms [I0] {5832} [DEBUG] (lcbio_mgr - L:247) <localhost:11210> (HE=0x2a30b00) Assigning R=0x2a7a920 SOCKET=0x2a46480
58080ms [I0] {5832} [DEBUG] (ioctx - L:101) <localhost:11210> (CTX=0x2a2b4b0,unknown) Pairing with SOCK=0x2a46480
58281ms [I0] {5832} [DEBUG] (negotiation - L:418) <localhost:11210> (SASLREQ=0x2a2b240) Server supports feature: 0x6 (XATTR)
58281ms [I0] {5832} [DEBUG] (negotiation - L:418) <localhost:11210> (SASLREQ=0x2a2b240) Server supports feature: 0x8 (Select Bucket)
58281ms [I0] {5832} [DEBUG] (negotiation - L:418) <localhost:11210> (SASLREQ=0x2a2b240) Server supports feature: 0x7 (Error Map)
58281ms [I0] {5832} [DEBUG] (negotiation - L:418) <localhost:11210> (SASLREQ=0x2a2b240) Server supports feature: 0x3 (TCP NODELAY)
58292ms [I0] {5832} [INFO] (negotiation - L:472) <localhost:11210> (SASLREQ=0x2a2b240) Sending SELECT_BUCKET
58293ms [I0] {5832} [DEBUG] (ioctx - L:151) <localhost:11210> (CTX=0x2a2b4b0,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
58293ms [I0] {5832} [DEBUG] (ioctx - L:101) <localhost:11210> (CTX=0x2a79990,unknown) Pairing with SOCK=0x2a46480
58322ms [I0] {5832} [DEBUG] (ioctx - L:151) <localhost:11210> (CTX=0x2a79990,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
58322ms [I0] {5832} [INFO] (lcbio_mgr - L:463) <localhost:11210> (HE=0x2a30b00) Placing socket back into the pool. I=0x2a54920,C=0x2a46480
58322ms [I0] {5832} [INFO] (confmon - L:158) Setting new configuration. Received via CCCP
58322ms [I0] {5832} [DEBUG] (bootstrap - L:56) Instance configured
58322ms [I0] {5832} [DEBUG] (confmon - L:85) Preparing providers (this may be called multiple times)
58322ms [I0] {5832} [DEBUG] (confmon - L:92) Provider CCCP is ENABLED
open: 58345.057ms
58351ms [I0] {5832} [INFO] (lcbio_mgr - L:406) <localhost:11210> (HE=0x2a30b00) Found ready connection in pool. Reusing socket and not creating new connection
58351ms [I0] {5832} [DEBUG] (lcbio_mgr - L:247) <localhost:11210> (HE=0x2a30b00) Assigning R=0x2a7d2a0 SOCKET=0x2a46480
58351ms [I0] {5832} [DEBUG] (ioctx - L:101) <localhost:11210> (CTX=0x2a7a080,unknown) Pairing with SOCK=0x2a46480
upsert: 80.211ms
dc: 0.159ms
ok
58490ms [I0] {5832} [DEBUG] (server - L:832) <localhost:11210> (SRV=0x2a7cf90,IX=0) Finalizing ctx 0x2a7a080
58490ms [I0] {5832} [DEBUG] (ioctx - L:151) <localhost:11210> (CTX=0x2a7a080,memcached) Destroying context. Pending Writes=0, Entered=false, Socket Refcount=1

Hey @kamran_saeedi,

It looks as though your DNS servers may be configured improperly. As part of the normal bootstrap procedure, we attempt to resolve SRV records for the hostname that is provided, it looks like you’re DNS servers may be timing out when trying to do this, causing a substantial delay when connecting. A quick way to test this theory is to add an additional hostname to your bootstrap list to disqualify the connection string from our DNS-SRV policy (for instance, use: couchbase://localhost,invalidhostname).

Cheers, Brett

1 Like

Hey @brett19,

That indeed was the case; and it was because I’ve been using a non-configured Ubuntu 16.04 without any post-install configuration.
Thank you and @avsej for your quick response.