Uploaded image for project: 'Couchbase C client library libcouchbase'
  1. Couchbase C client library libcouchbase
  2. CCBC-1532

Performance regression in MockUnitTest.testAppendE2BIG test when TLS is enabled

    XMLWordPrintable

Details

    • Bug
    • Status: Open
    • Critical
    • Resolution: Unresolved
    • 3.2.4
    • None
    • library
    • 1

    Description

      This test reliably takes 10x longer to run when TLS is enabled on the same cluster

      TLS disabled (254ms)

      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.
      

      TLS enabled (3448ms)

      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.
      

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          All tests fail when run with TLS in the lcb pipeline - raising this to a crit

          arunkumar Arunkumar Senthilnathan added a comment - All tests fail when run with TLS in the lcb pipeline - raising this to a crit

          nice find.

          It appears to be one test that does one too large operation and with ssl_noverify enabled? If it is a regression, then for sure we should figure it out. If it's been this way for a while, it might be something that is amortized over time with a long lived connection. Not right, but not terrible.

          What version did this regress from?

          also, arguably for a TLS test, we shouldn't be using ssl_noverify, even in our internal tests.

          ingenthr Matt Ingenthron added a comment - nice find. It appears to be one test that does one too large operation and with ssl_noverify enabled? If it is a regression, then for sure we should figure it out. If it's been this way for a while, it might be something that is amortized over time with a long lived connection. Not right, but not terrible. What version did this regress from? also, arguably for a TLS test, we shouldn't be using ssl_noverify, even in our internal tests.

          People

            avsej Sergey Avseyev
            jake.rawsthorne Jake Rawsthorne
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty