Uploaded image for project: 'Java Couchbase JVM Core'
  1. Java Couchbase JVM Core
  2. JVMCBC-709

SDK timed out with message 'KV SASL Negotiation timed out after 5000ms'

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • Major
    • None
    • 2.0.0-alpha.5
    • endpoint, KV
    • 3.0.0-alpha-5

    Description

      Server build: 6.5.0-3821-enterprise

      Scenario:

      1. 3 node cluster, Couchbase bucket (replica=1)
      2. Loading docs for DGM scenario.

      Observation:

      After loading around 140K of docs, got the below exception saying 'Did not observe any item or terminal signal within 5000ms'.

      Java console error:

      ExecutionException: java.util.concurrent.ExecutionException: reactor.core.Exceptions$ReactiveException: java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 5000ms in 'ignoreThen' (and no fallback has been configured)

      Client debug log prints:

      [WARN ] 2019-07-23 15:08:19.194 [cb-events] endpoint - [com.couchbase.endpoint][EndpointConnectionFailedEvent][5000000µs] Connect attempt 1 failed because of TimeoutException: Did not observe any item or terminal signal within 5000ms in 'source(MonoDefer)' (and no fallback has been configured) {"bucket":"default","circuitBreaker":"DISABLED","coreId":580,"remote":"10.112.191.101:11210","type":"KV"}
      [ERROR] 2019-07-23 15:08:19.196 [cb-io-kv-2321-1] Operators - Operator called default onErrorDropped
      java.util.concurrent.TimeoutException: KV SASL Negotiation timed out after 5000ms
          at com.couchbase.client.core.io.netty.kv.SaslAuthenticationHandler.lambda$channelActive$1(SaslAuthenticationHandler.java:164) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:127) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.channel.kqueue.KQueueEventLoop.run(KQueueEventLoop.java:293) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [core-io-2.0.0-alpha.5.jar:?]
          at com.couchbase.client.core.deps.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [core-io-2.0.0-alpha.5.jar:?]
          at java.lang.Thread.run(Thread.java:844) [?:?]
      [DEBUG] 2019-07-23 15:08:19.299 [cb-events] io - [com.couchbase.io][FeaturesNegotiatedEvent][526µs] Negotiated [XATTR, XERROR, SELECT_BUCKET, SNAPPY, ALT_REQUEST, SYNC_REPLICATION, COLLECTIONS] {"bucket":"default","coreId":580,"remote":"10.112.191.101/10.112.191.101:11210","local":"/10.112.191.1:58323"}
      [DEBUG] 2019-07-23 15:08:19.299 [cb-events] io - [com.couchbase.io][ErrorMapLoadedEvent][702µs] KV Error Map successfully loaded. Map Version: 1, Revision: 2 {"bucket":"default","coreId":580,"remote":"10.112.191.101/10.112.191.101:11210","local":"/10.112.191.1:58323"}
      [DEBUG] 2019-07-23 15:08:19.299 [cb-events] io - [com.couchbase.io][SaslMechanismsSelectedEvent] SASL Mechanism SCRAM_SHA512 selected. Server: [SCRAM_SHA1, SCRAM_SHA512, SCRAM_SHA256, PLAIN], Allowed: [PLAIN, CRAM_MD5, SCRAM_SHA1, SCRAM_SHA256, SCRAM_SHA512] {"bucket":"default","coreId":580,"remote":"10.112.191.101/10.112.191.101:11210","local":"/10.112.191.1:58323"}
      [DEBUG] 2019-07-23 15:08:19.299 [cb-events] io - [com.couchbase.io][SaslAuthenticationCompletedEvent][6709µs] SASL Authentication completed {"bucket":"default","coreId":580,"remote":"10.112.191.101/10.112.191.101:11210","local":"/10.112.191.1:58323"}
      

      Note: Not able to reproduce the same issue again. Try to reproduce with trace logs and update if we are able to reproduce this.

      TAF testcase:

      bucket_param_tests.dgm.Bucket_DGM_Tests.test_dgm_to_non_dgm,nodes_init=3,num_items=10000,doc_size=1024,active_resident_threshold=80,replicas=1,sdk_timeout=60,bucket_size=100

      Attachments

        1. JavaSDK.log
          19.18 MB
          Ashwin Govindarajulu
        2. test.log
          653 kB
          Ashwin Govindarajulu
        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            ashwin.govindarajulu Ashwin Govindarajulu
            ashwin.govindarajulu Ashwin Govindarajulu
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty