Performance regression in MockUnitTest.testAppendE2BIG test when TLS is enabled

export LCB_TEST_CLUSTER_CONF=couchbase://10.112.220.101,default,Administrator,password

./bin/unit-tests --gtest_filter="MockUnitTest.testAppendE2BIG"

Note: Google Test filter = MockUnitTest.testAppendE2BIG

[==========] Running 1 test from 1 test case.

[----------] 1 test from MockUnitTest

[ RUN      ] MockUnitTest.testAppendE2BIG

15ms [Ia1324e30f385b850] {37163/307} [INFO] (instance - L:521) Version=3.2.4_5_gccbaadf579, Changeset=ccbaadf579d3b4db6b3c63a931f9575443d66359

15ms [Ia1324e30f385b850] {37163/307} [INFO] (instance - L:522) Effective connection string: couchbase://10.112.220.101?dnssrv=off&bootstrap_on=cccp&compression=off. Bucket=default

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (instance - L:389) Applying initial cntl compression=off

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:8091 to initial HTTP bootstrap list

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:11210 to initial CCCP bootstrap list

16ms [Ia1324e30f385b850] {37163/307} [TRACE] (instance - L:193) Bootstrap hosts loaded (cccp:1, http:1)

16ms [Ia1324e30f385b850] {37163/307} [INFO] (bootstrap - L:277) Requested network configuration: heuristic

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (confmon - L:94) Preparing providers (this may be called multiple times)

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (confmon - L:100) Provider CCCP is ENABLED

16ms [Ia1324e30f385b850] {37163/307} [TRACE] (confmon - L:319) Refreshing current cluster map (bucket: default)

16ms [Ia1324e30f385b850] {37163/307} [TRACE] (confmon - L:305) Attempting to retrieve cluster map via CCCP

16ms [Ia1324e30f385b850] {37163/307} [INFO] (cccp - L:176) Requesting connection to node 10.112.220.101:11210 for CCCP configuration

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (lcbio_mgr - L:501) <10.112.220.101:11210> (HE=0x7ffeb1604130) Creating new connection because none are available in the pool

16ms [Ia1324e30f385b850] {37163/307} [TRACE] (lcbio_mgr - L:413) <10.112.220.101:11210> (HE=0x7ffeb1604130) New pool entry: I=0x7ffeb16043a0

16ms [Ia1324e30f385b850] {37163/307} [INFO] (connection - L:497) <10.112.220.101:11210> (SOCK=34482710baa714b8) Starting. Timeout=2000000us

16ms [Ia1324e30f385b850] {37163/307} [DEBUG] (connection - L:262) <10.112.220.101:11210> (SOCK=34482710baa714b8) Created new socket with FD=4

16ms [Ia1324e30f385b850] {37163/307} [TRACE] (connection - L:362) <10.112.220.101:11210> (SOCK=34482710baa714b8) Scheduling I/O watcher for asynchronous connection completion.

18ms [Ia1324e30f385b850] {37163/307} [INFO] (connection - L:159) <10.112.220.101:11210> (SOCK=34482710baa714b8) Connected established

18ms [Ia1324e30f385b850] {37163/307} [DEBUG] (connection - L:106) <10.112.220.101:11210> (SOCK=34482710baa714b8) Successfully set TCP_NODELAY

18ms [Ia1324e30f385b850] {37163/307} [DEBUG] (connection - L:106) <10.112.220.101:11210> (SOCK=34482710baa714b8) Successfully set TCP_KEEPALIVE

18ms [Ia1324e30f385b850] {37163/307} [DEBUG] (lcbio_mgr - L:369) <10.112.220.101:11210> (HE=0x7ffeb1604130) Received result for I=0x7ffeb16043a0,C=0x0; E=0x0

18ms [Ia1324e30f385b850] {37163/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11210> (HE=0x7ffeb1604130) Assigning R=0x7ffeb16042a0 SOCKET=0x7ffeb16045e0

18ms [Ia1324e30f385b850] {37163/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11210> (CTX=0x7ffeb1604760,unknown) Pairing with SOCK=34482710baa714b8

18ms [Ia1324e30f385b850] {37163/307} [DEBUG] (negotiation - L:471) <10.112.220.101:11210> (CTX=0x7ffeb1604760,sasl,SASLREQ=0x7ffe82009000) HELO identificator: {"a":"libcouchbase/3.2.4_5_gccbaadf579 (Darwin-19.6.0; x86_64; Clang 7.1.0)","i":"a1324e30f385b850/34482710baa714b8"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections), 0x0e (Unordered execution), 0x17 (Create as Deleted), 0x14 (Preserve Expiry)

24ms [Ia1324e30f385b850] {37163/307} [DEBUG] (negotiation - L:502) <10.112.220.101:11210> (CTX=0x7ffeb1604760,sasl,SASLREQ=0x7ffe82009000) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing), 0x12 (Collections), 0x14 (Preserve Expiry), 0x17 (Create as Deleted)

25ms [Ia1324e30f385b850] {37163/307} [DEBUG] (negotiation - L:326) <10.112.220.101:11210> (CTX=0x7ffeb1604760,sasl,SASLREQ=0x7ffe82009000) Using SCRAM-SHA512 SASL mechanism

36ms [Ia1324e30f385b850] {37163/307} [DEBUG] (negotiation - L:554) <10.112.220.101:11210> (CTX=0x7ffeb1604760,sasl,SASLREQ=0x7ffe82009000) Sending SELECT_BUCKET "default"

36ms [Ia1324e30f385b850] {37163/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11210> (CTX=0x7ffeb1604760,sasl) Destroying context for SOCK=34482710baa714b8. Pending Writes=0, Entered=true, Socket Refcount=1

36ms [Ia1324e30f385b850] {37163/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11210> (CTX=0x7ffeb29041f0,unknown) Pairing with SOCK=34482710baa714b8

37ms [Ia1324e30f385b850] {37163/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11210> (CTX=0x7ffeb29041f0,bc_cccp) Destroying context for SOCK=34482710baa714b8. Pending Writes=0, Entered=true, Socket Refcount=1

37ms [Ia1324e30f385b850] {37163/307} [DEBUG] (lcbio_mgr - L:554) <10.112.220.101:11210> (HE=0x7ffeb1604130) Placing socket back into the pool. I=0x7ffeb16043a0,C=0x7ffeb16045e0

38ms [Ia1324e30f385b850] {37163/307} [INFO] (confmon - L:183) Setting initial configuration. Received via CCCP (bucket="default", rev=1:65, address="10.112.220.101")

38ms [Ia1324e30f385b850] {37163/307} [INFO] (bootstrap - L:95) Selected network configuration: "default"

38ms [Ia1324e30f385b850] {37163/307} [DEBUG] (lcbio_mgr - L:492) <10.112.220.101:11210> (HE=0x7ffeb1604130) Found ready connection in pool. Reusing socket and not creating new connection

38ms [Ia1324e30f385b850] {37163/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11210> (HE=0x7ffeb1604130) Assigning R=0x7ffeb1510520 SOCKET=0x7ffeb16045e0

38ms [Ia1324e30f385b850] {37163/307} [TRACE] (server - L:1005) <10.112.220.101:11210> (SRV=0x7ffeb15135b0) Got new KV connection (json=yes, snappy=no, mt=yes, durability=no, bucket=yes "default")

38ms [Ia1324e30f385b850] {37163/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11210> (CTX=0x7ffeb2b040c0,unknown) Pairing with SOCK=34482710baa714b8

42ms [Ia1324e30f385b850] {37163/307} [DEBUG] (server - L:1214) <10.112.220.101:11210> (CTX=0x7ffeb2b040c0,memcached,SRV=0x7ffeb15135b0,IX=0) Finalizing context

42ms [Ia1324e30f385b850] {37163/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11210> (CTX=0x7ffeb2b040c0,memcached) Destroying context for SOCK=34482710baa714b8. Pending Writes=0, Entered=false, Socket Refcount=1

42ms [Ib5b9012b8046289] {37163/307} [INFO] (instance - L:521) Version=3.2.4_5_gccbaadf579, Changeset=ccbaadf579d3b4db6b3c63a931f9575443d66359

43ms [Ib5b9012b8046289] {37163/307} [INFO] (instance - L:522) Effective connection string: couchbase://10.112.220.101?dnssrv=off&bootstrap_on=cccp&compression=off. Bucket=default

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (instance - L:389) Applying initial cntl compression=off

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:8091 to initial HTTP bootstrap list

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:11210 to initial CCCP bootstrap list

43ms [Ib5b9012b8046289] {37163/307} [TRACE] (instance - L:193) Bootstrap hosts loaded (cccp:1, http:1)

43ms [Ib5b9012b8046289] {37163/307} [INFO] (bootstrap - L:277) Requested network configuration: heuristic

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (confmon - L:94) Preparing providers (this may be called multiple times)

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (confmon - L:100) Provider CCCP is ENABLED

43ms [Ib5b9012b8046289] {37163/307} [TRACE] (confmon - L:319) Refreshing current cluster map (bucket: default)

43ms [Ib5b9012b8046289] {37163/307} [TRACE] (confmon - L:305) Attempting to retrieve cluster map via CCCP

43ms [Ib5b9012b8046289] {37163/307} [INFO] (cccp - L:176) Requesting connection to node 10.112.220.101:11210 for CCCP configuration

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (lcbio_mgr - L:501) <10.112.220.101:11210> (HE=0x7ffeb2b04180) Creating new connection because none are available in the pool

43ms [Ib5b9012b8046289] {37163/307} [TRACE] (lcbio_mgr - L:413) <10.112.220.101:11210> (HE=0x7ffeb2b04180) New pool entry: I=0x7ffeb2b043e0

43ms [Ib5b9012b8046289] {37163/307} [INFO] (connection - L:497) <10.112.220.101:11210> (SOCK=3b1b8cc3c510373b) Starting. Timeout=2000000us

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (connection - L:262) <10.112.220.101:11210> (SOCK=3b1b8cc3c510373b) Created new socket with FD=4

43ms [Ib5b9012b8046289] {37163/307} [TRACE] (connection - L:362) <10.112.220.101:11210> (SOCK=3b1b8cc3c510373b) Scheduling I/O watcher for asynchronous connection completion.

43ms [Ib5b9012b8046289] {37163/307} [INFO] (connection - L:159) <10.112.220.101:11210> (SOCK=3b1b8cc3c510373b) Connected established

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (connection - L:106) <10.112.220.101:11210> (SOCK=3b1b8cc3c510373b) Successfully set TCP_NODELAY

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (connection - L:106) <10.112.220.101:11210> (SOCK=3b1b8cc3c510373b) Successfully set TCP_KEEPALIVE

43ms [Ib5b9012b8046289] {37163/307} [DEBUG] (lcbio_mgr - L:369) <10.112.220.101:11210> (HE=0x7ffeb2b04180) Received result for I=0x7ffeb2b043e0,C=0x0; E=0x0

44ms [Ib5b9012b8046289] {37163/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11210> (HE=0x7ffeb2b04180) Assigning R=0x7ffeb2b042c0 SOCKET=0x7ffeb2b04110

44ms [Ib5b9012b8046289] {37163/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11210> (CTX=0x7ffea14041d0,unknown) Pairing with SOCK=3b1b8cc3c510373b

44ms [Ib5b9012b8046289] {37163/307} [DEBUG] (negotiation - L:471) <10.112.220.101:11210> (CTX=0x7ffea14041d0,sasl,SASLREQ=0x7ffea200aa00) HELO identificator: {"a":"libcouchbase/3.2.4_5_gccbaadf579 (Darwin-19.6.0; x86_64; Clang 7.1.0)","i":"0b5b9012b8046289/3b1b8cc3c510373b"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections), 0x0e (Unordered execution), 0x17 (Create as Deleted), 0x14 (Preserve Expiry)

45ms [Ib5b9012b8046289] {37163/307} [DEBUG] (negotiation - L:502) <10.112.220.101:11210> (CTX=0x7ffea14041d0,sasl,SASLREQ=0x7ffea200aa00) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing), 0x12 (Collections), 0x14 (Preserve Expiry), 0x17 (Create as Deleted)

46ms [Ib5b9012b8046289] {37163/307} [DEBUG] (negotiation - L:326) <10.112.220.101:11210> (CTX=0x7ffea14041d0,sasl,SASLREQ=0x7ffea200aa00) Using SCRAM-SHA512 SASL mechanism

53ms [Ib5b9012b8046289] {37163/307} [DEBUG] (negotiation - L:554) <10.112.220.101:11210> (CTX=0x7ffea14041d0,sasl,SASLREQ=0x7ffea200aa00) Sending SELECT_BUCKET "default"

53ms [Ib5b9012b8046289] {37163/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11210> (CTX=0x7ffea14041d0,sasl) Destroying context for SOCK=3b1b8cc3c510373b. Pending Writes=0, Entered=true, Socket Refcount=1

53ms [Ib5b9012b8046289] {37163/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11210> (CTX=0x7ffeb141a130,unknown) Pairing with SOCK=3b1b8cc3c510373b

54ms [Ib5b9012b8046289] {37163/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11210> (CTX=0x7ffeb141a130,bc_cccp) Destroying context for SOCK=3b1b8cc3c510373b. Pending Writes=0, Entered=true, Socket Refcount=1

54ms [Ib5b9012b8046289] {37163/307} [DEBUG] (lcbio_mgr - L:554) <10.112.220.101:11210> (HE=0x7ffeb2b04180) Placing socket back into the pool. I=0x7ffeb2b043e0,C=0x7ffeb2b04110

54ms [Ib5b9012b8046289] {37163/307} [INFO] (confmon - L:183) Setting initial configuration. Received via CCCP (bucket="default", rev=1:65, address="10.112.220.101")

54ms [Ib5b9012b8046289] {37163/307} [INFO] (bootstrap - L:95) Selected network configuration: "default"

102ms [Ib5b9012b8046289] {37163/307} [DEBUG] (lcbio_mgr - L:492) <10.112.220.101:11210> (HE=0x7ffeb2b04180) Found ready connection in pool. Reusing socket and not creating new connection

104ms [Ib5b9012b8046289] {37163/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11210> (HE=0x7ffeb2b04180) Assigning R=0x7ffeb2904620 SOCKET=0x7ffeb2b04110

104ms [Ib5b9012b8046289] {37163/307} [TRACE] (server - L:1005) <10.112.220.101:11210> (SRV=0x7ffeb2a04250) Got new KV connection (json=yes, snappy=no, mt=yes, durability=no, bucket=yes "default")

104ms [Ib5b9012b8046289] {37163/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11210> (CTX=0x7ffeb141a130,unknown) Pairing with SOCK=3b1b8cc3c510373b

250ms [Ib5b9012b8046289] {37163/307} [DEBUG] (server - L:1214) <10.112.220.101:11210> (CTX=0x7ffeb141a130,memcached,SRV=0x7ffeb2a04250,IX=0) Finalizing context

250ms [Ib5b9012b8046289] {37163/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11210> (CTX=0x7ffeb141a130,memcached) Destroying context for SOCK=3b1b8cc3c510373b. Pending Writes=0, Entered=false, Socket Refcount=1

[       OK ] MockUnitTest.testAppendE2BIG (238 ms)

[----------] 1 test from MockUnitTest (238 ms total)

[----------] Global test environment tear-down

[==========] 1 test from 1 test case ran. (254 ms total)

[  PASSED  ] 1 test.

export LCB_TEST_CLUSTER_CONF=couchbases://10.112.220.101?ssl=no_verify,default,Administrator,password

./bin/unit-tests --gtest_filter="MockUnitTest.testAppendE2BIG"

Note: Google Test filter = MockUnitTest.testAppendE2BIG

[==========] Running 1 test from 1 test case.

[----------] 1 test from MockUnitTest

[ RUN      ] MockUnitTest.testAppendE2BIG

20ms [Id1e90db19e8e214c] {37139/307} [INFO] (instance - L:521) Version=3.2.4_5_gccbaadf579, Changeset=ccbaadf579d3b4db6b3c63a931f9575443d66359

20ms [Id1e90db19e8e214c] {37139/307} [INFO] (instance - L:522) Effective connection string: couchbases://10.112.220.101?ssl=no_verify&dnssrv=off&bootstrap_on=cccp&compression=off. Bucket=default

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (instance - L:389) Applying initial cntl compression=off

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:18091 to initial HTTP bootstrap list

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:11207 to initial CCCP bootstrap list

20ms [Id1e90db19e8e214c] {37139/307} [TRACE] (instance - L:193) Bootstrap hosts loaded (cccp:1, http:1)

20ms [Id1e90db19e8e214c] {37139/307} [INFO] (bootstrap - L:277) Requested network configuration: heuristic

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (confmon - L:94) Preparing providers (this may be called multiple times)

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (confmon - L:100) Provider CCCP is ENABLED

20ms [Id1e90db19e8e214c] {37139/307} [TRACE] (confmon - L:319) Refreshing current cluster map (bucket: default)

20ms [Id1e90db19e8e214c] {37139/307} [TRACE] (confmon - L:305) Attempting to retrieve cluster map via CCCP

20ms [Id1e90db19e8e214c] {37139/307} [INFO] (cccp - L:176) Requesting connection to node 10.112.220.101:11207 for CCCP configuration

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (lcbio_mgr - L:501) <10.112.220.101:11207> (HE=0x7f9171607690) Creating new connection because none are available in the pool

20ms [Id1e90db19e8e214c] {37139/307} [TRACE] (lcbio_mgr - L:413) <10.112.220.101:11207> (HE=0x7f9171607690) New pool entry: I=0x7f91716078d0

20ms [Id1e90db19e8e214c] {37139/307} [INFO] (connection - L:497) <10.112.220.101:11207> (SOCK=64ff158753430096) Starting. Timeout=2000000us

20ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (connection - L:262) <10.112.220.101:11207> (SOCK=64ff158753430096) Created new socket with FD=4

20ms [Id1e90db19e8e214c] {37139/307} [TRACE] (connection - L:362) <10.112.220.101:11207> (SOCK=64ff158753430096) Scheduling I/O watcher for asynchronous connection completion.

21ms [Id1e90db19e8e214c] {37139/307} [INFO] (connection - L:159) <10.112.220.101:11207> (SOCK=64ff158753430096) Connected established

21ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (connection - L:106) <10.112.220.101:11207> (SOCK=64ff158753430096) Successfully set TCP_NODELAY

21ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (connection - L:106) <10.112.220.101:11207> (SOCK=64ff158753430096) Successfully set TCP_KEEPALIVE

21ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (lcbio_mgr - L:369) <10.112.220.101:11207> (HE=0x7f9171607690) Received result for I=0x7f91716078d0,C=0x0; E=0x0

21ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11207> (HE=0x7f9171607690) Assigning R=0x7f91716077d0 SOCKET=0x7f9171607a90

21ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11207> (CTX=0x7f9171608730,unknown) Pairing with SOCK=64ff158753430096

21ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (negotiation - L:471) <10.112.220.101:11207> (CTX=0x7f9171608730,sasl,SASLREQ=0x7f9173812800) HELO identificator: {"a":"libcouchbase/3.2.4_5_gccbaadf579 (Darwin-19.6.0; x86_64; Clang 7.1.0)","i":"d1e90db19e8e214c/64ff158753430096"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections), 0x0e (Unordered execution), 0x17 (Create as Deleted), 0x14 (Preserve Expiry)

21ms [Id1e90db19e8e214c] {37139/307} [TRACE] (SSL - L:240) <10.112.220.101:11207> sock=0x7f9171607a90: ST(0x10). before SSL initialization. R(0x1) unknown (unknown)

24ms [Id1e90db19e8e214c] {37139/307} [TRACE] (SSL - L:240) <10.112.220.101:11207> sock=0x7f9171607a90: ST(0x20). SSL negotiation finished successfully. R(0x1) unknown (unknown)

24ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (SSL - L:245) sock=0x7f9171607a90. Using SSL version TLSv1.3. Cipher=TLS_AES_256_GCM_SHA384

25ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (negotiation - L:502) <10.112.220.101:11207> (CTX=0x7f9171608730,sasl,SASLREQ=0x7f9173812800) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing), 0x12 (Collections), 0x14 (Preserve Expiry), 0x17 (Create as Deleted)

26ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (negotiation - L:326) <10.112.220.101:11207> (CTX=0x7f9171608730,sasl,SASLREQ=0x7f9173812800) Using SCRAM-SHA512 SASL mechanism

31ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (negotiation - L:554) <10.112.220.101:11207> (CTX=0x7f9171608730,sasl,SASLREQ=0x7f9173812800) Sending SELECT_BUCKET "default"

31ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11207> (CTX=0x7f9171608730,sasl) Destroying context for SOCK=64ff158753430096. Pending Writes=0, Entered=true, Socket Refcount=1

31ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11207> (CTX=0x7f91723042f0,unknown) Pairing with SOCK=64ff158753430096

32ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11207> (CTX=0x7f91723042f0,bc_cccp) Destroying context for SOCK=64ff158753430096. Pending Writes=0, Entered=true, Socket Refcount=1

32ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (lcbio_mgr - L:554) <10.112.220.101:11207> (HE=0x7f9171607690) Placing socket back into the pool. I=0x7f91716078d0,C=0x7f9171607a90

32ms [Id1e90db19e8e214c] {37139/307} [INFO] (confmon - L:183) Setting initial configuration. Received via CCCP (bucket="default", rev=1:65, address="10.112.220.101")

32ms [Id1e90db19e8e214c] {37139/307} [INFO] (bootstrap - L:95) Selected network configuration: "default"

32ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (lcbio_mgr - L:492) <10.112.220.101:11207> (HE=0x7f9171607690) Found ready connection in pool. Reusing socket and not creating new connection

32ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11207> (HE=0x7f9171607690) Assigning R=0x7f9141405280 SOCKET=0x7f9171607a90

32ms [Id1e90db19e8e214c] {37139/307} [TRACE] (server - L:1005) <10.112.220.101:11207> (SRV=0x7f9141404480) Got new KV connection (json=yes, snappy=no, mt=yes, durability=no, bucket=yes "default")

32ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11207> (CTX=0x7f91722041b0,unknown) Pairing with SOCK=64ff158753430096

35ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (server - L:1214) <10.112.220.101:11207> (CTX=0x7f91722041b0,memcached,SRV=0x7f9141404480,IX=0) Finalizing context

35ms [Id1e90db19e8e214c] {37139/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11207> (CTX=0x7f91722041b0,memcached) Destroying context for SOCK=64ff158753430096. Pending Writes=0, Entered=false, Socket Refcount=1

35ms [I92f816ae2250a625] {37139/307} [INFO] (instance - L:521) Version=3.2.4_5_gccbaadf579, Changeset=ccbaadf579d3b4db6b3c63a931f9575443d66359

35ms [I92f816ae2250a625] {37139/307} [INFO] (instance - L:522) Effective connection string: couchbases://10.112.220.101?ssl=no_verify&dnssrv=off&bootstrap_on=cccp&compression=off. Bucket=default

35ms [I92f816ae2250a625] {37139/307} [DEBUG] (instance - L:389) Applying initial cntl compression=off

35ms [I92f816ae2250a625] {37139/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:18091 to initial HTTP bootstrap list

35ms [I92f816ae2250a625] {37139/307} [DEBUG] (instance - L:155) Adding host 10.112.220.101:11207 to initial CCCP bootstrap list

35ms [I92f816ae2250a625] {37139/307} [TRACE] (instance - L:193) Bootstrap hosts loaded (cccp:1, http:1)

35ms [I92f816ae2250a625] {37139/307} [INFO] (bootstrap - L:277) Requested network configuration: heuristic

35ms [I92f816ae2250a625] {37139/307} [DEBUG] (confmon - L:94) Preparing providers (this may be called multiple times)

35ms [I92f816ae2250a625] {37139/307} [DEBUG] (confmon - L:100) Provider CCCP is ENABLED

35ms [I92f816ae2250a625] {37139/307} [TRACE] (confmon - L:319) Refreshing current cluster map (bucket: default)

35ms [I92f816ae2250a625] {37139/307} [TRACE] (confmon - L:305) Attempting to retrieve cluster map via CCCP

35ms [I92f816ae2250a625] {37139/307} [INFO] (cccp - L:176) Requesting connection to node 10.112.220.101:11207 for CCCP configuration

35ms [I92f816ae2250a625] {37139/307} [DEBUG] (lcbio_mgr - L:501) <10.112.220.101:11207> (HE=0x7f91716045f0) Creating new connection because none are available in the pool

35ms [I92f816ae2250a625] {37139/307} [TRACE] (lcbio_mgr - L:413) <10.112.220.101:11207> (HE=0x7f91716045f0) New pool entry: I=0x7f9171604370

35ms [I92f816ae2250a625] {37139/307} [INFO] (connection - L:497) <10.112.220.101:11207> (SOCK=f70df4c504f863f3) Starting. Timeout=2000000us

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (connection - L:262) <10.112.220.101:11207> (SOCK=f70df4c504f863f3) Created new socket with FD=4

36ms [I92f816ae2250a625] {37139/307} [TRACE] (connection - L:362) <10.112.220.101:11207> (SOCK=f70df4c504f863f3) Scheduling I/O watcher for asynchronous connection completion.

36ms [I92f816ae2250a625] {37139/307} [INFO] (connection - L:159) <10.112.220.101:11207> (SOCK=f70df4c504f863f3) Connected established

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (connection - L:106) <10.112.220.101:11207> (SOCK=f70df4c504f863f3) Successfully set TCP_NODELAY

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (connection - L:106) <10.112.220.101:11207> (SOCK=f70df4c504f863f3) Successfully set TCP_KEEPALIVE

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (lcbio_mgr - L:369) <10.112.220.101:11207> (HE=0x7f91716045f0) Received result for I=0x7f9171604370,C=0x0; E=0x0

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11207> (HE=0x7f91716045f0) Assigning R=0x7f91716042a0 SOCKET=0x7f91716049e0

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11207> (CTX=0x7f9141407b00,unknown) Pairing with SOCK=f70df4c504f863f3

36ms [I92f816ae2250a625] {37139/307} [DEBUG] (negotiation - L:471) <10.112.220.101:11207> (CTX=0x7f9141407b00,sasl,SASLREQ=0x7f914200be00) HELO identificator: {"a":"libcouchbase/3.2.4_5_gccbaadf579 (Darwin-19.6.0; x86_64; Clang 7.1.0)","i":"92f816ae2250a625/f70df4c504f863f3"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections), 0x0e (Unordered execution), 0x17 (Create as Deleted), 0x14 (Preserve Expiry)

36ms [I92f816ae2250a625] {37139/307} [TRACE] (SSL - L:240) <10.112.220.101:11207> sock=0x7f91716049e0: ST(0x10). before SSL initialization. R(0x1) unknown (unknown)

39ms [I92f816ae2250a625] {37139/307} [TRACE] (SSL - L:240) <10.112.220.101:11207> sock=0x7f91716049e0: ST(0x20). SSL negotiation finished successfully. R(0x1) unknown (unknown)

39ms [I92f816ae2250a625] {37139/307} [DEBUG] (SSL - L:245) sock=0x7f91716049e0. Using SSL version TLSv1.3. Cipher=TLS_AES_256_GCM_SHA384

40ms [I92f816ae2250a625] {37139/307} [DEBUG] (negotiation - L:502) <10.112.220.101:11207> (CTX=0x7f9141407b00,sasl,SASLREQ=0x7f914200be00) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing), 0x12 (Collections), 0x14 (Preserve Expiry), 0x17 (Create as Deleted)

41ms [I92f816ae2250a625] {37139/307} [DEBUG] (negotiation - L:326) <10.112.220.101:11207> (CTX=0x7f9141407b00,sasl,SASLREQ=0x7f914200be00) Using SCRAM-SHA512 SASL mechanism

45ms [I92f816ae2250a625] {37139/307} [DEBUG] (negotiation - L:554) <10.112.220.101:11207> (CTX=0x7f9141407b00,sasl,SASLREQ=0x7f914200be00) Sending SELECT_BUCKET "default"

45ms [I92f816ae2250a625] {37139/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11207> (CTX=0x7f9141407b00,sasl) Destroying context for SOCK=f70df4c504f863f3. Pending Writes=0, Entered=true, Socket Refcount=1

45ms [I92f816ae2250a625] {37139/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11207> (CTX=0x7f91721041b0,unknown) Pairing with SOCK=f70df4c504f863f3

46ms [I92f816ae2250a625] {37139/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11207> (CTX=0x7f91721041b0,bc_cccp) Destroying context for SOCK=f70df4c504f863f3. Pending Writes=0, Entered=true, Socket Refcount=1

46ms [I92f816ae2250a625] {37139/307} [DEBUG] (lcbio_mgr - L:554) <10.112.220.101:11207> (HE=0x7f91716045f0) Placing socket back into the pool. I=0x7f9171604370,C=0x7f91716049e0

47ms [I92f816ae2250a625] {37139/307} [INFO] (confmon - L:183) Setting initial configuration. Received via CCCP (bucket="default", rev=1:65, address="10.112.220.101")

47ms [I92f816ae2250a625] {37139/307} [INFO] (bootstrap - L:95) Selected network configuration: "default"

92ms [I92f816ae2250a625] {37139/307} [DEBUG] (lcbio_mgr - L:492) <10.112.220.101:11207> (HE=0x7f91716045f0) Found ready connection in pool. Reusing socket and not creating new connection

94ms [I92f816ae2250a625] {37139/307} [DEBUG] (lcbio_mgr - L:329) <10.112.220.101:11207> (HE=0x7f91716045f0) Assigning R=0x7f917141a6c0 SOCKET=0x7f91716049e0

94ms [I92f816ae2250a625] {37139/307} [TRACE] (server - L:1005) <10.112.220.101:11207> (SRV=0x7f9171606f90) Got new KV connection (json=yes, snappy=no, mt=yes, durability=no, bucket=yes "default")

94ms [I92f816ae2250a625] {37139/307} [DEBUG] (ioctx - L:94) <10.112.220.101:11207> (CTX=0x7f9141407b00,unknown) Pairing with SOCK=f70df4c504f863f3

2749ms [I92f816ae2250a625] {37139/307} [TRACE] (bootstrap - L:176) Background-polling for new configuration

2749ms [I92f816ae2250a625] {37139/307} [TRACE] (confmon - L:319) Refreshing current cluster map (bucket: default)

2965ms [I92f816ae2250a625] {37139/307} [TRACE] (confmon - L:305) Attempting to retrieve cluster map via CCCP

2965ms [I92f816ae2250a625] {37139/307} [TRACE] (cccp - L:164) Re-Issuing CCCP Command on server struct 0x7f9171606f90 (10.112.220.101:11207)

3425ms [I92f816ae2250a625] {37139/307} [TRACE] (confmon - L:157) Not applying configuration received via CCCP (bucket="default", source=CCCP, address="10.112.220.101"). No changes detected. A.rev=1:65, B.rev=1:65. Changes: servers=no, map=no, replicas=no

3438ms [I92f816ae2250a625] {37139/307} [DEBUG] (server - L:1214) <10.112.220.101:11207> (CTX=0x7f9141407b00,memcached,SRV=0x7f9171606f90,IX=0) Finalizing context

3438ms [I92f816ae2250a625] {37139/307} [DEBUG] (ioctx - L:140) <10.112.220.101:11207> (CTX=0x7f9141407b00,memcached) Destroying context for SOCK=f70df4c504f863f3. Pending Writes=0, Entered=false, Socket Refcount=1

3447ms [I92f816ae2250a625] {37139/307} [INFO] (tracer - L:175) Operations over threshold: {"count":1,"service":"kv","top":[{"last_dispatch_duration_us":3332256,"last_local_id":"92f816ae2250a625/f70df4c504f863f3","last_local_socket":"10.112.220.1:52034","last_operation_id":"0","last_remote_socket":"10.112.220.101:11207","last_server_duration_us":3958,"operation_name":"upsert","total_dispatch_duration_us":3332256,"total_duration_us":3332256,"total_server_duration_us":3958}]}

[       OK ] MockUnitTest.testAppendE2BIG (3428 ms)

[----------] 1 test from MockUnitTest (3428 ms total)

[----------] Global test environment tear-down

[==========] 1 test from 1 test case ran. (3448 ms total)

[  PASSED  ] 1 test.