search

bwgjoseph / mongoose-vs-ottoman

feature comparison between mongoose and ottoman
0 stars 1 forks source link

start() doesn't seem to trigger ensureCollections #97

Closed bwgjoseph closed 3 years ago

bwgjoseph commented 3 years ago

Hi,

Based on my understanding, and what was described in the docs, when running start(), it will trigger ensureCollections and ensureIndexes.

And so I was trying to connect to couchbase with new scope and collection but it doesn't seem to creates it when start() is triggered

This is the sample code

const initOttoman = async (consistency: SearchConsistency = SearchConsistency.NONE) => {
    const ottoman = new Ottoman({ scopeName: '_default', collectionName: '_default1', consistency });

    ottoman.connect({
        connectionString: 'couchbase://localhost',
        bucketName: 'testBucket',
        username: 'user',
        password: 'password'
    });

    // this should ensure the scope and collection are created
    await ottoman.start();

    return ottoman;
}

describe('test populate function', async () => {
    before(async () => {
        await initOttoman(SearchConsistency.LOCAL);
    });

    it('ottoman - populate', async () => {
        // some codes
    });
});

Here's the logs output for your reference

$ npm test

> mongoose-vs-ottoman@1.0.0 test Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman
> mocha --require ts-node/register test/ts/populate.test.ts --exit

  test populate function
  couchnode:lcb:info (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:503) Version=3.0.7-njs, Changeset=d2d3666e269b41413408aaae96eb289f1cb4f8ec +0ms
  couchnode:lcb:info (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:504) Effective connection string: couchbase://localhost/testBucket?client_string=couchnode%2F3.1.1%20(node%2F14.15.3%3B%20v8%2F8.4.371.19-node.17%3B%20ssl%2F1.1.1g). Bucket=testBucket +3ms
  couchnode:lcb:debug (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:372) Applying initial cntl client_string=couchnode/3.1.1 (node/14.15.3; v8/8.4.371.19-node.17; ssl/1.1.1g) +0ms
  couchnode:lcb:info (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:195) DNS SRV lookup failed: LCB_ERR_UNKNOWN_HOST (1049). Ignore this if not relying on DNS SRV records +9ms
  couchnode:lcb:debug (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:138) Adding host localhost:8091 to initial HTTP bootstrap list +8ms
  couchnode:lcb:debug (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:138) Adding host localhost:11210 to initial CCCP bootstrap list +1ms
  couchnode:lcb:trace (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:176) Bootstrap hosts loaded (cccp:1, http:1) +0ms
  couchnode:lcb:info (bootstrap @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bootstrap.cc:270) Requested network configuration: heuristic +2ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:94) Preparing providers (this may be called multiple times) +1ms      
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:100) Provider CCCP is ENABLED +0ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:100) Provider HTTP is ENABLED +1ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:314) Refreshing current cluster map (bucket: testBucket) +2ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:300) Attempting to retrieve cluster map via CCCP +5ms
  couchnode:lcb:info (cccp @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\bc_cccp.cc:176) Requesting connection to node localhost:11210 for CCCP configuration 
+6ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:501) <localhost:11210> (HE=0000028B6E36D840) Creating new connection because none are available in the pool +7ms
  couchnode:lcb:trace (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:413) <localhost:11210> (HE=0000028B6E36D840) New pool entry: I=0000028B6C8264D0 +3ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:485) <localhost:11210> (SOCK=c172252c75342f3b) Starting. Timeout=2000000us 
+3ms
  couchnode:lcb:trace (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:381) <localhost:11210> (SOCK=c172252c75342f3b) Received completion handler. Status=0. errno=0 [No error] +15ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:153) <localhost:11210> (SOCK=c172252c75342f3b) Connected established +16ms 
  couchnode:lcb:warn (lcbio @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ioutils.cc:107) Translating errno=0, lcb=0x401 to NETWORK_ERROR +0ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:108) <localhost:11210> (SOCK=c172252c75342f3b) Couldn't set TCP_NODELAY +3ms
  couchnode:lcb:debug (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:106) <localhost:11210> (SOCK=c172252c75342f3b) Successfully set TCP_KEEPALIVE +21ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:369) <localhost:11210> (HE=0000028B6E36D840) Received result for I=0000028B6C8264D0,C=0000000000000000; E=0x0 +1ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:11210> (HE=0000028B6E36D840) Assigning R=0000028B6C826470 SOCKET=0000028B6C7F4B90 +1ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:11210> (CTX=0000028B6F209610,unknown) Pairing with SOCK=c172252c75342f3b +2ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:456) <localhost:11210> (CTX=0000028B6F209610,sasl,SASLREQ=0000028B6F65C820) HELO identificator: {"a":"libcouchbase/3.0.7-njs couchnode/3.1.1 (node/14.15.3; v8/8.4.371.19-node.17; ssl/1.1.1g)","i":"9392f3aa6132651f/c172252c75342f3b"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x0a (Snappy), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections), 0x0e (Unordered execution), 0x17 (Create as Deleted) +1ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:487) <localhost:11210> (CTX=0000028B6F209610,sasl,SASLREQ=0000028B6F65C820) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0a (Snappy), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing), 0x12 (Collections), 0x17 (Create as Deleted) +3ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:316) <localhost:11210> (CTX=0000028B6F209610,sasl,SASLREQ=0000028B6F65C820) Using SCRAM-SHA512 SASL mechanism +1ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:539) <localhost:11210> (CTX=0000028B6F209610,sasl,SASLREQ=0000028B6F65C820) Sending SELECT_BUCKET "testBucket" +6ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:11210> (CTX=0000028B6F209610,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1 +2ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:11210> (CTX=0000028B6F20A7F0,unknown) Pairing with SOCK=c172252c75342f3b +0ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:11210> (CTX=0000028B6F20A7F0,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1 +2ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:554) <localhost:11210> (HE=0000028B6E36D840) Placing socket back into the pool. I=0000028B6C8264D0,C=0000028B6C7F4B90 +1ms
  couchnode:lcb:info (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:179) Setting initial configuration. Received via CCCP (bucket="testBucket", rev=98, address="localhost") +21ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:94) Preparing providers (this may be called multiple times) +1ms      
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:100) Provider CCCP is ENABLED +0ms
  couchnode:lcb:info (bootstrap @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bootstrap.cc:91) Selected network configuration: "default" +1ms
  couchnode:lcb:trace (http-io @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\http\http.cc:392) <localhost:8093> POST  http://localhost:8093/query/service. Body=206 bytes +28ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:501) <localhost:8093> (HE=0000028B6E2600E0) Creating new connection because none are available in the pool +2ms
  couchnode:lcb:trace (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:413) <localhost:8093> (HE=0000028B6E2600E0) New pool entry: I=0000028B6C826470 +1ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:485) <localhost:8093> (SOCK=49eded3b6b2c0643) Starting. Timeout=75000000us 
+4ms
  couchnode:lcb:trace (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:381) <localhost:8093> (SOCK=49eded3b6b2c0643) Received completion handler. Status=0. errno=0 [No error] +2ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:153) <localhost:8093> (SOCK=49eded3b6b2c0643) Connected established +1ms   
  couchnode:lcb:warn (lcbio @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ioutils.cc:107) Translating errno=0, lcb=0x401 to NETWORK_ERROR +29ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:108) <localhost:8093> (SOCK=49eded3b6b2c0643) Couldn't set TCP_NODELAY +1ms  couchnode:lcb:debug (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:106) <localhost:8093> (SOCK=49eded3b6b2c0643) Successfully set TCP_KEEPALIVE +5ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:369) <localhost:8093> (HE=0000028B6E2600E0) Received result for I=0000028B6C826470,C=0000000000000000; E=0x0 +0ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:8093> (HE=0000028B6E2600E0) Assigning R=0000028B6C826830 SOCKET=0000028B6E55CC20 +0ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:8093> (CTX=0000028B6F209610,unknown) Pairing with SOCK=49eded3b6b2c0643 +1ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:8093> (CTX=0000028B6F209610,mgmt/capi) Destroying context. Pending 
Writes=0, Entered=true, Socket Refcount=1 +40ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:554) <localhost:8093> (HE=0000028B6E2600E0) Placing socket back into the pool. I=0000028B6C826470,C=0000028B6E55CC20 +0ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:492) <localhost:11210> (HE=0000028B6E36D840) Found ready connection in pool. Reusing socket and not creating new connection +6ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:11210> (HE=0000028B6E36D840) Assigning R=0000028B6C826950 SOCKET=0000028B6C7F4B90 +1ms
  couchnode:lcb:trace (server @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\mcserver.cc:996) <localhost:11210> (SRV=0000028B6F2A8A60) Got new KV connection (json=yes, snappy=yes, mt=yes, durability=no, bucket=yes "testBucket") +50ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:11210> (CTX=0000028B6F209D60,unknown) Pairing with SOCK=c172252c75342f3b +1ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EDBF0 to retry queue. retries=1, opaque=0, time=3773us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +2ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 9 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EDBF0 to network. retries=1, opaque=0, IX=0, time=23265us +19ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1ED800 to retry queue. retries=2, opaque=0, time=25840us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +22ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 19 ms +4ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1ED800 to network. retries=2, opaque=0, IX=0, time=54724us +28ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EE4F0 to retry queue. retries=3, opaque=0, time=58836us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +33ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 29 ms +5ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EE4F0 to network. retries=3, opaque=0, IX=0, time=102203us 
+42ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1ED260 to retry queue. retries=4, opaque=0, time=104888us, 
status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +46ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 39 ms +4ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1ED260 to network. retries=4, opaque=0, IX=0, time=149287us 
+43ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EEC40 to retry queue. retries=5, opaque=0, time=189671us, 
status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +85ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 49 ms +42ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EEC40 to network. retries=5, opaque=0, IX=0, time=242248us 
+51ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EEDF0 to retry queue. retries=6, opaque=0, time=250250us, 
status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +60ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 59 ms +9ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EEDF0 to network. retries=6, opaque=0, IX=0, time=320136us 
+69ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1ED260 to retry queue. retries=7, opaque=0, time=344960us, 
status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +95ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 69 ms +26ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1ED260 to network. retries=7, opaque=0, IX=0, time=413816us 
+68ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1ED2F0 to retry queue. retries=8, opaque=0, time=416108us, 
status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +71ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 79 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1ED2F0 to network. retries=8, opaque=0, IX=0, time=507944us 
+91ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1ED1D0 to retry queue. retries=9, opaque=0, time=509777us, 
status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +94ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 89 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1ED1D0 to network. retries=9, opaque=0, IX=0, time=601875us 
+91ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EEC40 to retry queue. retries=10, opaque=0, time=606318us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +97ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 99 ms +5ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EEC40 to network. retries=10, opaque=0, IX=0, time=713145us +106ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EECD0 to retry queue. retries=11, opaque=0, time=716471us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +110ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 108 ms +5ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EECD0 to network. retries=11, opaque=0, IX=0, time=839257us +121ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1ED1D0 to retry queue. retries=12, opaque=0, time=841163us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +124ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 119 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1ED1D0 to network. retries=12, opaque=0, IX=0, time=966452us +125ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EDEC0 to retry queue. retries=13, opaque=0, time=1034167us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +193ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 129 ms +68ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EDEC0 to network. retries=13, opaque=0, IX=0, time=1170194us +135ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EE4F0 to retry queue. retries=14, opaque=0, time=1176115us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +142ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 137 ms +8ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EE4F0 to network. retries=14, opaque=0, IX=0, time=1328445us +151ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EEA90 to retry queue. retries=15, opaque=0, time=1333187us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +157ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 148 ms +6ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EEA90 to network. retries=15, opaque=0, IX=0, time=1485888us +151ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EE8E0 to retry queue. retries=16, opaque=0, time=1488760us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +156ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 159 ms +4ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EE8E0 to network. retries=16, opaque=0, IX=0, time=1656948us +167ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EE2B0 to retry queue. retries=17, opaque=0, time=1662996us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +174ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 167 ms +8ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=0000028B6E1EE2B0 to network. retries=17, opaque=0, IX=0, time=1832248us +168ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=0000028B6E1EDAD0 to retry queue. retries=18, opaque=0, time=1839189us, status=0x88, rc=LCB_ERR_COLLECTION_NOT_FOUND (211) +177ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 177 ms +9ms
    1) ottoman - populate

  0 passing (2s)
  1 failing

  1) test populate function
       ottoman - populate:
     Error: Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman\test\ts\populate.test.ts)
      at listOnTimeout (internal/timers.js:554:17)
      at processTimers (internal/timers.js:497:7)

npm ERR! Test failed.  See above for more details.

If I were to use an existing scope and collection, then it runs fine without any issue.

Also, we had a discussion previously on displaying debug logs for ottoman in https://github.com/bwgjoseph/mongoose-vs-ottoman/issues/4#issuecomment-794308476 but I can't recall how I should set it so that more logs will be output hence, there's only couchnode logs

Let me know if there's additional information required

Thanks

AV25242 commented 3 years ago
  1. Documentation to set nodejs environment variables https://ottomanjs.com/guides/ottoman.html#setting-environment-variables
  2. If set('DEBUG', true); is used createScope and createCollection methods will print in console information about scopes/collections created.
  3. Set a higher value to the timeout (>2000ms), and try again the start function should create the _default1 collection inside the _default scope (this scope always exists and don't be recreated by Ottoman)
bwgjoseph commented 3 years ago

@AV25242

So I added debug above the initialization

const initOttoman = async (consistency: SearchConsistency = SearchConsistency.NONE) => {
    set('DEBUG', true);

    const ottoman = new Ottoman({ scopeName: '_default', collectionName: '_default1', consistency });

   // rest of code

and set the test timeout to 10000 and now it shows this error without any additional logs from ottoman

test populate function
       ottoman - populate:
     Error: collection not found
      at _getWrappedErr (node_modules\couchbase\lib\errors.js:836:14)
      at Object.wrapLcbErr (node_modules\couchbase\lib\errors.js:1009:20)
      at Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman\node_modules\couchbase\lib\collection.js:572:24

Couple of things,

  1. no additional logs from ottoman with debug set to true
  2. collection still not getting created
  3. this scope always exists and don't be recreated by Ottoman < what does this mean? ottoman don't create new scope? Based on the doc, scope and collection should both be created by ottoman
  4. I shouldn't be increasing the timeout but for the sake of testing this out, I did and it still does not help
AV25242 commented 3 years ago

@bwgjoseph your collection name starts with an underscore which is not allowed, sorry I should have noticed earlier. Can you try with a common name ?

https://docs.couchbase.com/server/current/developer-preview/collections/collections-overview.html

bwgjoseph commented 3 years ago

If I don't increase the timeout, it will throw a timeout exceeded error by mocha (I believe) since the default is 2000ms.

After I set to 10000ms, and change the scope and collection to without underscore, it still doesn't work

This is the full error

$ npm test

> mongoose-vs-ottoman@1.0.0 test Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman
> mocha --require ts-node/register test/ts/populate.test.ts --exit

  test populate function
  couchnode:lcb:info (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:503) Version=3.0.7-njs, Changeset=d2d3666e269b41413408aaae96eb289f1cb4f8ec +0ms
  couchnode:lcb:info (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:504) Effective connection string: couchbase://localhost/testBucket?client_string=couchnode%2F3.1.1%20(node%2F14.15.3%3B%20v8%2F8.4.371.19-node.17%3B%20ssl%2F1.1.1g). Bucket=testBucket +1ms
  couchnode:lcb:debug (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:372) Applying initial cntl client_string=couchnode/3.1.1 (node/14.15.3; v8/8.4.371.19-node.17; ssl/1.1.1g) +0ms
  couchnode:lcb:info (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:195) DNS SRV lookup failed: LCB_ERR_UNKNOWN_HOST (1049). Ignore this if not relying on DNS SRV records +8ms
  couchnode:lcb:debug (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:138) Adding host localhost:8091 to initial HTTP bootstrap list +8ms
  couchnode:lcb:debug (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:138) Adding host localhost:11210 to initial CCCP bootstrap list +1ms
  couchnode:lcb:trace (instance @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\instance.cc:176) Bootstrap hosts loaded (cccp:1, http:1) +0ms
  couchnode:lcb:info (bootstrap @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bootstrap.cc:270) Requested network configuration: heuristic +2ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:94) Preparing providers (this may be called multiple times) +1ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:100) Provider CCCP is ENABLED +0ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:100) Provider HTTP is ENABLED +0ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:314) Refreshing current cluster map (bucket: testBucket) +2ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:300) Attempting to retrieve cluster map via CCCP +3ms
  couchnode:lcb:info (cccp @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\bc_cccp.cc:176) Requesting connection to node localhost:11210 for CCCP configuration +6ms      
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:501) <localhost:11210> (HE=000001A2D26C7B40) Creating new connection because none are available in the pool +5ms
  couchnode:lcb:trace (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:413) <localhost:11210> (HE=000001A2D26C7B40) New pool entry: I=000001A2D3710BC0 +2ms 
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:485) <localhost:11210> (SOCK=58f68c95db8d206b) Starting. Timeout=2000000us +1ms      
  couchnode:lcb:trace (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:381) <localhost:11210> (SOCK=58f68c95db8d206b) Received completion handler. Status=0. errno=0 [No error] +9ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:153) <localhost:11210> (SOCK=58f68c95db8d206b) Connected established +13ms
  couchnode:lcb:warn (lcbio @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ioutils.cc:107) Translating errno=0, lcb=0x401 to NETWORK_ERROR +0ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:108) <localhost:11210> (SOCK=58f68c95db8d206b) Couldn't set TCP_NODELAY +7ms
  couchnode:lcb:debug (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:106) <localhost:11210> (SOCK=58f68c95db8d206b) Successfully set TCP_KEEPALIVE +22ms 
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:369) <localhost:11210> (HE=000001A2D26C7B40) Received result for I=000001A2D3710BC0,C=0000000000000000; E=0x0 +0ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:11210> (HE=000001A2D26C7B40) Assigning R=000001A2D3710C80 SOCKET=000001A2D0C11890 +1ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:11210> (CTX=000001A2D283BFA0,unknown) Pairing with SOCK=58f68c95db8d206b +1ms 
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:456) <localhost:11210> (CTX=000001A2D283BFA0,sasl,SASLREQ=000001A2D264FBB0) HELO identificator: {"a":"libcouchbase/3.0.7-njs couchnode/3.1.1 (node/14.15.3; v8/8.4.371.19-node.17; ssl/1.1.1g)","i":"bba9b873f2bae6b0/58f68c95db8d206b"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 
(XERROR), 0x03 (TCP nodelay), 0x0a (Snappy), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections), 0x0e (Unordered execution), 0x17 (Create as Deleted) +0ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:487) <localhost:11210> (CTX=000001A2D283BFA0,sasl,SASLREQ=000001A2D264FBB0) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0a (Snappy), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing), 0x12 (Collections), 0x17 (Create as Deleted) +6ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:316) <localhost:11210> (CTX=000001A2D283BFA0,sasl,SASLREQ=000001A2D264FBB0) Using SCRAM-SHA512 SASL mechanism +1ms
  couchnode:lcb:debug (negotiation @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\negotiate.cc:539) <localhost:11210> (CTX=000001A2D283BFA0,sasl,SASLREQ=000001A2D264FBB0) Sending SELECT_BUCKET "testBucket" +6ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:11210> (CTX=000001A2D283BFA0,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1 +2ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:11210> (CTX=000001A2D283A0C0,unknown) Pairing with SOCK=58f68c95db8d206b +0ms 
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:11210> (CTX=000001A2D283A0C0,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1 +6ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:554) <localhost:11210> (HE=000001A2D26C7B40) Placing socket back into the pool. I=000001A2D3710BC0,C=000001A2D0C11890 +1ms
  couchnode:lcb:info (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:179) Setting initial configuration. Received via CCCP (bucket="testBucket", rev=155, address="localhost") +25ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:94) Preparing providers (this may be called multiple times) +1ms
  couchnode:lcb:debug (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:100) Provider CCCP is ENABLED +1ms
  couchnode:lcb:info (bootstrap @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bootstrap.cc:91) Selected network configuration: "default" +2ms
  couchnode:lcb:trace (http-io @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\http\http.cc:392) <localhost:8093> POST  http://localhost:8093/query/service. Body=206 bytes +39ms      
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:501) <localhost:8093> (HE=000001A2D372C290) Creating new connection because none are 
available in the pool +2ms
  couchnode:lcb:trace (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:413) <localhost:8093> (HE=000001A2D372C290) New pool entry: I=000001A2D3710C20 +2ms  
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:485) <localhost:8093> (SOCK=c08d3cd21e170516) Starting. Timeout=75000000us +3ms      
  couchnode:lcb:trace (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:381) <localhost:8093> (SOCK=c08d3cd21e170516) Received completion handler. Status=0. errno=0 [No error] +1ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:153) <localhost:8093> (SOCK=c08d3cd21e170516) Connected established +2ms
  couchnode:lcb:warn (lcbio @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ioutils.cc:107) Translating errno=0, lcb=0x401 to NETWORK_ERROR +33ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:108) <localhost:8093> (SOCK=c08d3cd21e170516) Couldn't set TCP_NODELAY +0ms
  couchnode:lcb:debug (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:106) <localhost:8093> (SOCK=c08d3cd21e170516) Successfully set TCP_KEEPALIVE +4ms   
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:369) <localhost:8093> (HE=000001A2D372C290) Received result for I=000001A2D3710C20,C=0000000000000000; E=0x0 +0ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:8093> (HE=000001A2D372C290) Assigning R=000001A2D0C3FB70 SOCKET=000001A2D0C115F0 +1ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:8093> (CTX=000001A2D283AF60,unknown) Pairing with SOCK=c08d3cd21e170516 +0ms  
  couchnode:lcb:trace (http-io @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\http\http.cc:392) <localhost:8093> POST  http://localhost:8093/query/service. Body=149 bytes +171ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:501) <localhost:8093> (HE=000001A2D372C290) Creating new connection because none are 
available in the pool +169ms
  couchnode:lcb:trace (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:413) <localhost:8093> (HE=000001A2D372C290) New pool entry: I=000001A2D2666210 +2ms  
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:485) <localhost:8093> (SOCK=1be1556ce9daaa5d) Starting. Timeout=75000000us +172ms    
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:8093> (CTX=000001A2D283AF60,mgmt/capi) Destroying context. Pending Writes=0, 
Entered=true, Socket Refcount=1 +2ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:554) <localhost:8093> (HE=000001A2D372C290) Placing socket back into the pool. I=000001A2D3710C20,C=000001A2D0C115F0 +1ms
  couchnode:lcb:trace (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:381) <localhost:8093> (SOCK=1be1556ce9daaa5d) Received completion handler. Status=0. errno=0 [No error] +2ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:153) <localhost:8093> (SOCK=1be1556ce9daaa5d) Connected established +3ms
  couchnode:lcb:warn (lcbio @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ioutils.cc:107) Translating errno=0, lcb=0x401 to NETWORK_ERROR +175ms
  couchnode:lcb:info (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:108) <localhost:8093> (SOCK=1be1556ce9daaa5d) Couldn't set TCP_NODELAY +0ms
  couchnode:lcb:debug (connection @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\connect.cc:106) <localhost:8093> (SOCK=1be1556ce9daaa5d) Successfully set TCP_KEEPALIVE +2ms   
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:369) <localhost:8093> (HE=000001A2D372C290) Received result for I=000001A2D2666210,C=0000000000000000; E=0x0 +0ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:8093> (HE=000001A2D372C290) Assigning R=000001A2D2666510 SOCKET=000001A2D35E68A0 +0ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:8093> (CTX=000001A2D2839F20,unknown) Pairing with SOCK=1be1556ce9daaa5d +1ms  
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:139) <localhost:8093> (CTX=000001A2D2839F20,mgmt/capi) Destroying context. Pending Writes=0, 
Entered=true, Socket Refcount=1 +316ms
  couchnode:lcb:info (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:550) <localhost:8093> (HE=000001A2D372C290) Closing idle connection. Too many in quota +318ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:492) <localhost:11210> (HE=000001A2D26C7B40) Found ready connection in pool. Reusing 
socket and not creating new connection +8ms
  couchnode:lcb:debug (lcbio_mgr @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\manager.cc:329) <localhost:11210> (HE=000001A2D26C7B40) Assigning R=000001A2D3710C80 SOCKET=000001A2D0C11890 +0ms
  couchnode:lcb:trace (server @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\mcserver\mcserver.cc:996) <localhost:11210> (SRV=000001A2D2737260) Got new KV connection (json=yes, snappy=yes, mt=yes, durability=no, bucket=yes "testBucket") +328ms
  couchnode:lcb:debug (ioctx @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\lcbio\ctx.cc:94) <localhost:11210> (CTX=000001A2D283AF60,unknown) Pairing with SOCK=58f68c95db8d206b +1ms 
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D26336A0 to retry queue. retries=1, opaque=0, time=3368us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +2ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 9 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D26336A0 to network. retries=1, opaque=0, IX=0, time=20668us +16ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=2, opaque=0, time=22417us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +19ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 19 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633CD0 to network. retries=2, opaque=0, IX=0, time=52166us +29ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633070 to retry queue. retries=3, opaque=0, time=54935us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +33ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 29 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633070 to network. retries=3, opaque=0, IX=0, time=98306us +43ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633D60 to retry queue. retries=4, opaque=0, time=102239us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +47ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 39 ms +4ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633D60 to network. retries=4, opaque=0, IX=0, time=145945us +44ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=5, opaque=0, time=147765us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +45ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 49 ms +2ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633CD0 to network. retries=5, opaque=0, IX=0, time=209812us +61ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633D60 to retry queue. retries=6, opaque=0, time=211470us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +64ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 59 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633D60 to network. retries=6, opaque=0, IX=0, time=273392us +61ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D26333D0 to retry queue. retries=7, opaque=0, time=275481us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +64ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 69 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D26333D0 to network. retries=7, opaque=0, IX=0, time=353172us +77ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633070 to retry queue. retries=8, opaque=0, time=354896us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +80ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 79 ms +2ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633070 to network. retries=8, opaque=0, IX=0, time=448209us +93ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D26336A0 to retry queue. retries=9, opaque=0, time=450380us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +95ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 89 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D26336A0 to network. retries=9, opaque=0, IX=0, time=541747us +90ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=10, opaque=0, time=543453us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +93ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 99 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633CD0 to network. retries=10, opaque=0, IX=0, time=653637us +109ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D26336A0 to retry queue. retries=11, opaque=0, time=655771us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +112ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 109 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D26336A0 to network. retries=11, opaque=0, IX=0, time=779407us +123ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633E80 to retry queue. retries=12, opaque=0, time=781281us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +126ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 119 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633E80 to network. retries=12, opaque=0, IX=0, time=905152us +123ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633070 to retry queue. retries=13, opaque=0, time=907103us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +126ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 129 ms +2ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633070 to network. retries=13, opaque=0, IX=0, time=1045172us +138ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=14, opaque=0, time=1054397us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +147ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 138 ms +10ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633CD0 to network. retries=14, opaque=0, IX=0, time=1201093us +146ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633D60 to retry queue. retries=15, opaque=0, time=1203292us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +149ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 149 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633D60 to network. retries=15, opaque=0, IX=0, time=1360658us +156ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D26336A0 to retry queue. retries=16, opaque=0, time=1362573us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +159ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 159 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D26336A0 to network. retries=16, opaque=0, IX=0, time=1533507us +170ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=17, opaque=0, time=1535267us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +173ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 169 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633CD0 to network. retries=17, opaque=0, IX=0, time=1704426us +168ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633D60 to retry queue. retries=18, opaque=0, time=1706537us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +171ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 179 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633D60 to network. retries=18, opaque=0, IX=0, time=1890046us +183ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=19, opaque=0, time=1892476us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +186ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 189 ms +3ms
  couchnode:lcb:trace (bootstrap @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bootstrap.cc:169) Background-polling for new configuration +105ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:314) Refreshing current cluster map (bucket: testBucket) +1ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:300) Attempting to retrieve cluster map via CCCP +1ms
  couchnode:lcb:trace (cccp @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\bc_cccp.cc:164) Re-Issuing CCCP Command on server struct 000001A2D2737260 (localhost:11210) +0ms
  couchnode:lcb:trace (confmon @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\bucketconfig\confmon.cc:157) Not applying configuration received via CCCP (bucket="testBucket", source=CCCP, address="localhost"). No changes detected. A.rev=155, B.rev=155. Changes: servers=no, map=no, replicas=no +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633CD0 to network. retries=19, opaque=0, IX=0, time=2091748us +88ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633D60 to retry queue. retries=20, opaque=0, time=2093806us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +201ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 199 ms +3ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:270) Flush PKT=000001A2D2633D60 to network. retries=20, opaque=0, IX=0, time=2293332us +199ms
  couchnode:lcb:debug (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:396) Adding PKT=000001A2D2633CD0 to retry queue. retries=21, opaque=0, time=2295360us, status=0x8c, rc=LCB_ERR_SCOPE_NOT_FOUND (217) +202ms
  couchnode:lcb:trace (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:202) Next tick in 203 ms +3ms
  couchnode:lcb:warn (retryq @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\retryq.cc:163) Failing command (pkt=000001A2D2633CD0, opaque=0, retries=21, time=2510558us, status=0x8c) from retry queue: LCB_ERR_SCOPE_NOT_FOUND (217) +3s
  couchnode:lcb:debug (collcache @ C:\Jenkins\workspace\nodejs\couchnode\couchnode-scripted-build-pipeline\couchnode\deps\lcb\src\collections.h:90) failed to resolve collection, rc: LCB_ERR_SCOPE_NOT_FOUND (217) +216ms
    1) ottoman - populate

  0 passing (3s)
  1 failing

  1) test populate function
       ottoman - populate:
     Error: scope not found
      at _getWrappedErr (node_modules\couchbase\lib\errors.js:848:14)
      at Object.wrapLcbErr (node_modules\couchbase\lib\errors.js:1009:20)
      at Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman\node_modules\couchbase\lib\collection.js:572:24

npm ERR! Test failed.  See above for more details.

This is what I've changed to

const initOttoman = async (consistency: SearchConsistency = SearchConsistency.NONE) => {
    set('DEBUG', true);

    const ottoman = new Ottoman({ scopeName: 'test', collectionName: 'test1', consistency });

    ottoman.connect({
        connectionString: 'couchbase://localhost',
        bucketName: 'testBucket',
        username: 'user',
        password: 'password'
    });

    await ottoman.start();

    await removeDocuments();

    return ottoman;
}

So the observation is still the same mentioned previously in https://github.com/bwgjoseph/mongoose-vs-ottoman/issues/97#issuecomment-864428735

AV25242 commented 3 years ago

@bwgjoseph you are also missing declaring models, models need to be declared first

bwgjoseph commented 3 years ago

Alright, so this is what I have

import assert from 'assert';
import { model, Schema, SearchConsistency, Ottoman, set, getModel } from 'ottoman';
import { removeDocuments } from './setup/util';

let postModel: any;
let commentModel: any;

const initOttoman = async (consistency: SearchConsistency = SearchConsistency.NONE) => {
    set('DEBUG', true);

    const ottoman = new Ottoman({ scopeName: 'samp', collectionName: 'samp1', consistency });

    ottoman.connect({
        connectionString: 'couchbase://localhost',
        bucketName: 'testBucket',
        username: 'user',
        password: 'password'
    });

    const postSchema = new Schema({ title: String, createdAt: { type: Date, default: () => new Date() } });
    const commentSchema = new Schema({ text: String, post: { type: String, ref: 'post' }});

    postModel = getModel('post') || model('post', postSchema);
    commentModel = getModel('comment') || model('comment', commentSchema);

    await ottoman.start();

    await removeDocuments();

    return ottoman;
}

describe('test populate function', async () => {
    before(async () => {
        await initOttoman(SearchConsistency.LOCAL);
    });

    it('ottoman - populate', async () => {
        const post = await postModel.create({ title: 'titleA' });
        const comment = await commentModel.create({ text: 'commentA', post: post.id });

        const populateA = await comment._populate();
        assert.deepStrictEqual(populateA.post, post);

        const { rows: populateB } = await commentModel.find({}, { populate: 'post' });
        console.log(populateB);
        assert.deepStrictEqual(populateB[0].post, post);

        const { rows: populateC } = await commentModel.find({}, { populate: { post: { select: ['id', 'title'] }} });
        assert.deepStrictEqual(populateC[0].post.id, post.id);
        assert.deepStrictEqual(populateC[0].post.title, post.title);
    });
});

So the first time I ran the script, it will show this

test populate function
Scope created:  samp
collection created: samp/samp1
    1) "before all" hook for "ottoman - populate"

  0 passing (2s)
  1 failing

  1) test populate function
       "before all" hook for "ottoman - populate":
     Error: Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman\test\ts\populate.test.ts)
      at listOnTimeout (internal/timers.js:554:17)
      at processTimers (internal/timers.js:497:7)

npm ERR! Test failed.  See above for more details.

Then I ran it again, and I will get the path exist error

$ npm test

> mongoose-vs-ottoman@1.0.0 test Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman
> mocha --require ts-node/register test/ts/populate.test.ts --exit

  test populate function
    1) ottoman - populate

  0 passing (1s)
  1 failing

  1) test populate function
       ottoman - populate:
     Error: path exists
      at _getWrappedErr (node_modules\couchbase\lib\errors.js:904:14)
      at Object.wrapLcbErr (node_modules\couchbase\lib\errors.js:1009:20)
      at Z:\Development\workspace\github\bwgjoseph\mongoose-vs-ottoman\node_modules\couchbase\lib\queryexecutor.js:126:26

npm ERR! Test failed.  See above for more details.

Then I ran again, and this time and subsequent time will be fine. The behavior is quite consistent with the path exists error whenever I change to a new scope/collection and run the script

Am I missing something again?

Question:

Why is it that there is no issue if I declare model after the start if I'm using back the existing scope/collection but there will be issue if I'm pointing to a new scope/collection?

gsi-alejandro commented 3 years ago

Hi @bwgjoseph

The problem is: The indexes aren't ready to use yet. then couchbase throws the 'path exists' error while querying with indexes don't ready yet.

Everything works after a short delay, due to all the indexes are online and ready to work.

In a web server environment, this error almost never occurs. but in the test environment, we run the suite tests right after creating the database structure (scopes/collections/indexes), usually, it's solved in CI or other OPS with sleep(5) in OS or delay(5000) in Javascript. (delay value change depending on server provisioning and database records to index if you use seeders or just adding index to existing documents)

bwgjoseph commented 3 years ago

@gsi-alejandro

path exists error message is quite cryptic, does path exists error always means that the indexes aren't ready?

I agree that we can make a delay (somewhat) to wait for the indexes to be ready but if there is no feedback from the database, then how would I know (as developer) how long should the delay be? Say my test has 50 models, which connects to 50 different scope/collection, would that 5 sec be sufficient for the database to be ready? Do I always need to guess what should my sleep timing be?

I thought that this should be handled within the ottoman or node SDK or the underlying C lib (if necessary) to ensure all indexes are ready before ottoman.start() really starts. Hence as a developer, I don't need to worry about sleeping my application

AV25242 commented 3 years ago

Provided an explanation to this in #90

bwgjoseph commented 3 years ago

Closing this in favor of #103