Couchbase disconnecting from node immediately after creating bucket using java sdk

willpowell · July 8, 2019, 12:24pm

Hi,

I’m developing an integration test suite for a project used to load data into couchbase. I am running both the project and couchbase in docker containers, with the couchbase image couchbase/server:community-4.5.1 and the couchbase client version 2.5.5.

When my project initialises, it connects to the couchbase cluster, opens the default bucket, then creates two additional buckets. I have an intermittent bug, approximately 1/5 runs when connecting to the default bucket, where couchbase connects to the node, then immediately disconnects. When this happens, there is a timeout exception and the application closes. The logs for this can be seen below:

local | INFO  | 2019-07-08T11:46:13,425 | [INDEXER] | {main} | CouchbaseCore | CouchbaseEnvironment: {sslEnabled=false, sslKeystoreFile='null', sslTruststoreFile='null', sslKeystorePassword=false, sslTruststorePassword=false, sslKeystore=null, sslTruststore=null, bootstrapHttpEnabled=true, bootstrapCarrierEnabled=true, bootstrapHttpDirectPort=8091, bootstrapHttpSslPort=18091, bootstrapCarrierDirectPort=11210, bootstrapCarrierSslPort=11207, ioPoolSize=6, computationPoolSize=6, responseBufferSize=16384, requestBufferSize=16384, kvServiceEndpoints=2, viewServiceEndpoints=12, queryServiceEndpoints=12, searchServiceEndpoints=12, configPollInterval=2500, configPollFloorInterval=50, ioPool=NioEventLoopGroup, kvIoPool=null, viewIoPool=null, searchIoPool=null, queryIoPool=null, coreScheduler=CoreScheduler, memcachedHashingStrategy=DefaultMemcachedHashingStrategy, eventBus=DefaultEventBus, packageNameAndVersion=couchbase-java-client/2.5.5 (git: 2.5.5, core: 1.5.5), retryStrategy=BestEffort, maxRequestLifetime=75000, retryDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=100, upper=100000}, reconnectDelay=ExponentialDelay{growBy 1.0 MILLISECONDS, powers of 2; lower=32, upper=4096}, observeIntervalDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=10, upper=100000}, keepAliveInterval=30000, continuousKeepAliveEnabled=true, keepAliveErrorThreshold=4, keepAliveTimeout=2500, autoreleaseAfter=2000, bufferPoolingEnabled=true, tcpNodelayEnabled=true, mutationTokensEnabled=false, socketConnectTimeout=60000, callbacksOnIoPool=false, disconnectTimeout=25000, requestBufferWaitStrategy=com.couchbase.client.core.env.DefaultCoreEnvironment$2@1c5c616f, certAuthEnabled=false, coreSendHook=null, forceSaslPlain=false, queryTimeout=75000, viewTimeout=75000, searchTimeout=75000, analyticsTimeout=75000, kvTimeout=60000, connectTimeout=60000, dnsSrvEnabled=false}
local | INFO  | 2019-07-08T11:46:14,316 | [INDEXER] | {cb-io-1-2} | Node | Connected to Node 192.168.128.3/tc-ncUUVfZo.08e52656-d0fa-4329-887e-19662614eafd
local | INFO  | 2019-07-08T11:46:14,322 | [INDEXER] | {cb-io-1-2} | Node | Disconnected from Node 192.168.128.3/tc-ncUUVfZo.08e52656-d0fa-4329-887e-19662614eafd
local | ERROR | 2019-07-08T11:47:13,508 | [INDEXER] | {main} | IndexerRunner | Error while setting up Indexer
java.lang.RuntimeException: java.util.concurrent.TimeoutException
at com.couchbase.client.core.utils.Blocking.blockForSingle(Blocking.java:74) ~[indexer.jar:2.0.0]
at com.couchbase.client.java.CouchbaseCluster.openBucket(CouchbaseCluster.java:344) ~[indexer.jar:2.0.0]
at com.couchbase.client.java.CouchbaseCluster.openBucket(CouchbaseCluster.java:322) ~[indexer.jar:2.0.0]
at com.tesco.ess.indexer.services.CouchbaseClient.openBucket(CouchbaseClient.java:83) ~[indexer.jar:2.0.0]
at com.tesco.ess.indexer.services.CouchbaseAdmin.<init>(CouchbaseAdmin.java:46) ~[indexer.jar:2.0.0]
at com.tesco.ess.indexer.CamelContextHelper.setupCouchbaseService(CamelContextHelper.java:104) ~[indexer.jar:2.0.0]
at com.tesco.ess.indexer.IndexerRunner.<init>(IndexerRunner.java:45) [indexer.jar:2.0.0]
at com.tesco.ess.indexer.IndexerRunner.main(IndexerRunner.java:32) [indexer.jar:2.0.0]
Caused by: java.util.concurrent.TimeoutException
... 8 more

We also encounter this bug in production, but Kubernetes restarts the pod and the application eventually starts successfully.

Any help would be appreciated!

willpowell · July 8, 2019, 4:04pm

Adding some DEBUG level logs:

local | DEBUG | 2019-07-08T15:48:42,849 | [INDEXER] | {main} | Netty4Transport | connected to node [{aZSHBr9}{aZSHBr9_QKCv5uxcJdxgeQ}{ezin0_b8SsaUiMc5VSqJdQ}{172.25.0.2}{172.25.0.2:9300}]
local | INFO  | 2019-07-08T15:48:42,868 | [INDEXER] | {main} | CouchbaseClient | Returning clutser from properties file couchbase
local | DEBUG | 2019-07-08T15:48:42,902 | [INDEXER] | {main} | CouchbaseLoggerFactory | Using SLF4J as the default logging framework
local | DEBUG | 2019-07-08T15:48:42,909 | [INDEXER] | {main} | InternalLoggerFactory | Using SLF4J as the default logging framework
local | DEBUG | 2019-07-08T15:48:42,944 | [INDEXER] | {main} | MultithreadEventLoopGroup | -Dio.netty.eventLoopThreads: 12
local | DEBUG | 2019-07-08T15:48:42,992 | [INDEXER] | {main} | PlatformDependent0 | -Dio.netty.noUnsafe: false
local | DEBUG | 2019-07-08T15:48:42,993 | [INDEXER] | {main} | PlatformDependent0 | Java version: 8
local | DEBUG | 2019-07-08T15:48:42,995 | [INDEXER] | {main} | PlatformDependent0 | sun.misc.Unsafe.theUnsafe: available
local | DEBUG | 2019-07-08T15:48:42,998 | [INDEXER] | {main} | PlatformDependent0 | sun.misc.Unsafe.copyMemory: available
local | DEBUG | 2019-07-08T15:48:42,999 | [INDEXER] | {main} | PlatformDependent0 | java.nio.Buffer.address: available
local | DEBUG | 2019-07-08T15:48:43,000 | [INDEXER] | {main} | PlatformDependent0 | direct buffer constructor: available
local | DEBUG | 2019-07-08T15:48:43,002 | [INDEXER] | {main} | PlatformDependent0 | java.nio.Bits.unaligned: available, true
local | DEBUG | 2019-07-08T15:48:43,002 | [INDEXER] | {main} | PlatformDependent0 | jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
local | DEBUG | 2019-07-08T15:48:43,002 | [INDEXER] | {main} | PlatformDependent0 | java.nio.DirectByteBuffer.<init>(long, int): available
local | DEBUG | 2019-07-08T15:48:43,002 | [INDEXER] | {main} | PlatformDependent | sun.misc.Unsafe: available
local | DEBUG | 2019-07-08T15:48:43,003 | [INDEXER] | {main} | PlatformDependent | -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
local | DEBUG | 2019-07-08T15:48:43,003 | [INDEXER] | {main} | PlatformDependent | -Dio.netty.bitMode: 64 (sun.arch.data.model)
local | DEBUG | 2019-07-08T15:48:43,005 | [INDEXER] | {main} | PlatformDependent | -Dio.netty.noPreferDirect: false
local | DEBUG | 2019-07-08T15:48:43,005 | [INDEXER] | {main} | PlatformDependent | -Dio.netty.maxDirectMemory: 1858600960 bytes
local | DEBUG | 2019-07-08T15:48:43,005 | [INDEXER] | {main} | PlatformDependent | -Dio.netty.uninitializedArrayAllocationThreshold: -1
local | DEBUG | 2019-07-08T15:48:43,008 | [INDEXER] | {main} | CleanerJava6 | java.nio.ByteBuffer.cleaner(): available
local | DEBUG | 2019-07-08T15:48:43,047 | [INDEXER] | {main} | NioEventLoop | -Dio.netty.noKeySetOptimization: false
local | DEBUG | 2019-07-08T15:48:43,047 | [INDEXER] | {main} | NioEventLoop | -Dio.netty.selectorAutoRebuildThreshold: 512
local | DEBUG | 2019-07-08T15:48:43,068 | [INDEXER] | {main} | PlatformDependent | org.jctools-core.MpscChunkedArrayQueue: available
local | INFO  | 2019-07-08T15:48:43,206 | [INDEXER] | {main} | CouchbaseCore | CouchbaseEnvironment: {sslEnabled=false, sslKeystoreFile='null', sslTruststoreFile='null', sslKeystorePassword=false, sslTruststorePassword=false, sslKeystore=null, sslTruststore=null, bootstrapHttpEnabled=true, bootstrapCarrierEnabled=true, bootstrapHttpDirectPort=8091, bootstrapHttpSslPort=18091, bootstrapCarrierDirectPort=11210, bootstrapCarrierSslPort=11207, ioPoolSize=6, computationPoolSize=6, responseBufferSize=16384, requestBufferSize=16384, kvServiceEndpoints=2, viewServiceEndpoints=12, queryServiceEndpoints=12, searchServiceEndpoints=12, configPollInterval=2500, configPollFloorInterval=50, ioPool=NioEventLoopGroup, kvIoPool=null, viewIoPool=null, searchIoPool=null, queryIoPool=null, coreScheduler=CoreScheduler, memcachedHashingStrategy=DefaultMemcachedHashingStrategy, eventBus=DefaultEventBus, packageNameAndVersion=couchbase-java-client/2.5.5 (git: 2.5.5, core: 1.5.5), retryStrategy=BestEffort, maxRequestLifetime=75000, retryDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=100, upper=100000}, reconnectDelay=ExponentialDelay{growBy 1.0 MILLISECONDS, powers of 2; lower=32, upper=4096}, observeIntervalDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=10, upper=100000}, keepAliveInterval=30000, continuousKeepAliveEnabled=true, keepAliveErrorThreshold=4, keepAliveTimeout=2500, autoreleaseAfter=2000, bufferPoolingEnabled=true, tcpNodelayEnabled=true, mutationTokensEnabled=false, socketConnectTimeout=60000, callbacksOnIoPool=false, disconnectTimeout=25000, requestBufferWaitStrategy=com.couchbase.client.core.env.DefaultCoreEnvironment$2@1c6c6f24, certAuthEnabled=false, coreSendHook=null, forceSaslPlain=false, queryTimeout=75000, viewTimeout=75000, searchTimeout=75000, analyticsTimeout=75000, kvTimeout=60000, connectTimeout=60000, dnsSrvEnabled=false}
local | DEBUG | 2019-07-08T15:48:43,210 | [INDEXER] | {main} | CouchbaseCore | Diagnostics {
  gc.ps marksweep.collectionCount=2,
  gc.ps marksweep.collectionTime=90,
  gc.ps scavenge.collectionCount=7,
  gc.ps scavenge.collectionTime=57,
  heap.pendingFinalize=0,
  heap.used=init = 132120576(129024K) used = 24383664(23812K) committed = 143654912(140288K) max = 1858600960(1815040K),
  mem.physical.free=2965999616,
  mem.physical.total=8360390656,
  mem.swap.free=1073049600,
  mem.swap.total=1073737728,
  mem.virtual.comitted=3763277824,
  offHeap.used=init = 2555904(2496K) used = 56700344(55371K) committed = 58572800(57200K) max = -1(-1K),
  proc.cpu.time=11240000000,
  runtime.name=64@224d28144dee,
  runtime.spec=Oracle Corporation/Java Virtual Machine Specification: 1.8,
  runtime.startTime=1562600915437,
  runtime.sysProperties={awt.toolkit=sun.awt.X11.XToolkit, file.encoding.pkg=sun.io, java.specification.version=1.8, com.couchbase.client.deps.io.netty.packagePrefix=com.couchbase.client.deps., log4j.configurationFile=log4j2.xml, sun.cpu.isalist=, sun.jnu.encoding=UTF-8, java.class.path=.:indexer.jar:/usr/share/appdynamics/appagent/javaagent.jar, java.vm.vendor=Oracle Corporation, io.netty.recycler.maxCapacityPerThread=0, sun.arch.data.model=64, java.vendor.url=http://java.oracle.com/, user.timezone=GMT, os.name=Linux, java.vm.specification.version=1.8, user.country=US, sun.java.launcher=SUN_STANDARD, sun.boot.library.path=/usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64, sun.java.command=com.tesco.ess.indexer.IndexerRunner, sun.cpu.endian=little, user.home=/root, user.language=en, io.netty.noKeySetOptimization=true, java.specification.vendor=Oracle Corporation, java.home=/usr/lib/jvm/java-1.8-openjdk/jre, file.separator=/, line.separator=
, java.vm.specification.vendor=Oracle Corporation, java.specification.name=Java Platform API Specification, java.awt.graphicsenv=sun.awt.X11GraphicsEnvironment, sun.boot.class.path=/usr/lib/jvm/java-1.8-openjdk/jre/lib/resources.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/rt.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jsse.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jce.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/charsets.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jfr.jar:/usr/lib/jvm/java-1.8-openjdk/jre/classes:/usr/share/appdynamics/appagent/javaagent.jar, sun.management.compiler=HotSpot 64-Bit Tiered Compilers, io.netty.noUnsafe=true, java.runtime.version=1.8.0_121-b13, user.name=root, path.separator=:, os.version=4.9.125-linuxkit, java.endorsed.dirs=/usr/lib/jvm/java-1.8-openjdk/jre/lib/endorsed, java.runtime.name=OpenJDK Runtime Environment, file.encoding=UTF-8, sun.nio.ch.bugLevel=, java.vm.name=OpenJDK 64-Bit Server VM, org.apache.camel.jmx.disabled=true, java.vendor.url.bug=http://bugreport.sun.com/bugreport/, java.io.tmpdir=/tmp, java.version=1.8.0_121, user.dir=/opt/app, os.arch=amd64, java.vm.specification.name=Java Virtual Machine Specification, java.awt.printerjob=sun.print.PSPrinterJob, sun.os.patch.level=unknown, java.library.path=/usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64/server:/usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64:/usr/lib/jvm/java-1.8-openjdk/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib, java.vm.info=mixed mode, java.vendor=Oracle Corporation, java.vm.version=25.121-b13, io.netty.allocator.type=unpooled, java.ext.dirs=/usr/lib/jvm/java-1.8-openjdk/jre/lib/ext:/usr/java/packages/lib/ext, sun.io.unicode.encoding=UnicodeLittle, java.class.version=52.0},
  runtime.uptime=7992,
  runtime.vm=Oracle Corporation/OpenJDK 64-Bit Server VM: 25.121-b13,
  sys.cpu.loadAvg=1.83935546875,
  sys.cpu.num=6,
  sys.os.arch=amd64,
  sys.os.name=Linux,
  sys.os.version=4.9.125-linuxkit,
  thread.count=31,
  thread.peakCount=31,
  thread.startedCount=33
}
local | DEBUG | 2019-07-08T15:48:43,223 | [INDEXER] | {main} | CarrierRefresher | Starting polling with interval 2500ms
local | DEBUG | 2019-07-08T15:48:43,297 | [INDEXER] | {main} | ConfigurationProvider | Setting seed hosts to [NetworkAddress{/172.25.0.3, fromHostname=false, reverseDns=true}]
local | DEBUG | 2019-07-08T15:48:43,331 | [INDEXER] | {main} | ConfigurationProvider | Got instructed to open bucket default

local | DEBUG | 2019-07-08T15:48:43,593 | [INDEXER] | {cb-computations-6} | ByteBufUtil | -Dio.netty.allocator.type: unpooled
local | DEBUG | 2019-07-08T15:48:43,594 | [INDEXER] | {cb-computations-6} | ByteBufUtil | -Dio.netty.threadLocalDirectBufferSize: 65536
local | DEBUG | 2019-07-08T15:48:43,594 | [INDEXER] | {cb-computations-6} | ByteBufUtil | -Dio.netty.maxThreadLocalCharBufferSize: 16384
local | DEBUG | 2019-07-08T15:48:43,608 | [INDEXER] | {cb-computations-6} | Service | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289][KeyValueService]: Connecting Endpoint during Service connect.
local | DEBUG | 2019-07-08T15:48:43,952 | [INDEXER] | {cb-io-1-1} | AbstractByteBuf | -Dcom.couchbase.client.deps.io.netty.buffer.bytebuf.checkAccessible: true
local | DEBUG | 2019-07-08T15:48:43,954 | [INDEXER] | {cb-io-1-1} | ResourceLeakDetectorFactory | Loaded default ResourceLeakDetector: com.couchbase.client.deps.io.netty.util.ResourceLeakDetector@37bdf401
local | DEBUG | 2019-07-08T15:48:43,956 | [INDEXER] | {cb-io-1-1} | KeyValueFeatureHandler | Requesting supported features: [TCPNODELAY, XATTR, SELECT_BUCKET, SNAPPY, XERROR]
local | DEBUG | 2019-07-08T15:48:43,956 | [INDEXER] | {cb-io-1-2} | KeyValueFeatureHandler | Requesting supported features: [TCPNODELAY, XATTR, SELECT_BUCKET, SNAPPY, XERROR]
local | DEBUG | 2019-07-08T15:48:43,966 | [INDEXER] | {cb-io-1-2} | Recycler | -Dio.netty.recycler.maxCapacity.default: 32768
local | DEBUG | 2019-07-08T15:48:43,966 | [INDEXER] | {cb-io-1-2} | Recycler | -Dio.netty.recycler.maxSharedCapacityFactor: 2
local | DEBUG | 2019-07-08T15:48:43,966 | [INDEXER] | {cb-io-1-2} | Recycler | -Dio.netty.recycler.linkCapacity: 16
local | DEBUG | 2019-07-08T15:48:43,967 | [INDEXER] | {cb-io-1-2} | Recycler | -Dio.netty.recycler.ratio: 8
local | DEBUG | 2019-07-08T15:48:44,008 | [INDEXER] | {cb-io-1-1} | KeyValueFeatureHandler | Negotiated supported features: [TCPNODELAY]
local | DEBUG | 2019-07-08T15:48:44,008 | [INDEXER] | {cb-io-1-2} | KeyValueFeatureHandler | Negotiated supported features: [TCPNODELAY]
local | DEBUG | 2019-07-08T15:48:44,164 | [INDEXER] | {cb-io-1-2} | Endpoint | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3:11210][KeyValueEndpoint]: Connected Endpoint.
local | DEBUG | 2019-07-08T15:48:44,164 | [INDEXER] | {cb-io-1-1} | Endpoint | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3:11210][KeyValueEndpoint]: Connected Endpoint.
local | INFO  | 2019-07-08T15:48:44,168 | [INDEXER] | {cb-io-1-2} | Node | Connected to Node 172.25.0.3/tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289
local | DEBUG | 2019-07-08T15:48:44,172 | [INDEXER] | {cb-io-1-2} | Node | Connected (CONNECTING) to Node NetworkAddress{tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3, fromHostname=false, reverseDns=true}
local | INFO  | 2019-07-08T15:48:44,174 | [INDEXER] | {cb-io-1-2} | Node | Disconnected from Node 172.25.0.3/tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289
local | DEBUG | 2019-07-08T15:48:44,174 | [INDEXER] | {cb-io-1-1} | AbstractGenericHandler | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3:11210][KeyValueEndpoint]: Channel Active.
local | DEBUG | 2019-07-08T15:48:44,176 | [INDEXER] | {cb-io-1-2} | Node | Disconnected (CONNECTED) from Node NetworkAddress{tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3, fromHostname=false, reverseDns=true}
local | DEBUG | 2019-07-08T15:48:44,180 | [INDEXER] | {cb-computations-2} | Loader | Successfully enabled Service BINARY on Node NetworkAddress{tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3, fromHostname=false, reverseDns=true}
local | DEBUG | 2019-07-08T15:48:44,180 | [INDEXER] | {cb-io-1-2} | AbstractGenericHandler | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3:11210][KeyValueEndpoint]: Channel Active.
local | DEBUG | 2019-07-08T15:48:44,180 | [INDEXER] | {cb-computations-2} | CarrierLoader | Starting to discover config through Carrier Bootstrap
local | DEBUG | 2019-07-08T15:48:45,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:48:45,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:48:48,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:48:48,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:48:50,690 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:48:50,690 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:48:53,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:48:53,226 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:48:55,724 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:48:55,724 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:48:58,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:48:58,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:00,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:00,726 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:03,224 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:03,224 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:05,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:05,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:08,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:08,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:10,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:10,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:13,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:13,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:14,148 | [INDEXER] | {cb-io-1-2} | AbstractGenericHandler | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3:11210][KeyValueEndpoint]: KeepAlive fired
local | DEBUG | 2019-07-08T15:49:14,148 | [INDEXER] | {cb-io-1-1} | AbstractGenericHandler | [tc-ykH4xfpT.e041dc71-ec0e-45ef-8eec-2e2230217289/172.25.0.3:11210][KeyValueEndpoint]: KeepAlive fired
local | DEBUG | 2019-07-08T15:49:15,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:15,726 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:18,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:18,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:20,692 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:20,693 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:23,227 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:23,228 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:25,724 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:25,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:28,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:28,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:30,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:30,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:33,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:33,226 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:35,724 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:35,725 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:38,225 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:38,226 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:40,724 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:40,724 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | DEBUG | 2019-07-08T15:49:43,226 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Received signal to proactively refresh (a maybe outdated) configuration.
local | DEBUG | 2019-07-08T15:49:43,226 | [INDEXER] | {cb-computations-4} | ConfigurationProvider | Ignoring outdated signal, since no buckets are open.
local | ERROR | 2019-07-08T15:49:43,337 | [INDEXER] | {main} | IndexerRunner | Error while setting up Indexer
java.lang.RuntimeException: java.util.concurrent.TimeoutException
	at com.couchbase.client.core.utils.Blocking.blockForSingle(Blocking.java:74) ~[indexer.jar:2.0.0]
	at com.couchbase.client.java.CouchbaseCluster.openBucket(CouchbaseCluster.java:344) ~[indexer.jar:2.0.0]
	at com.couchbase.client.java.CouchbaseCluster.openBucket(CouchbaseCluster.java:322) ~[indexer.jar:2.0.0]
	at com.tesco.ess.indexer.services.CouchbaseClient.openBucket(CouchbaseClient.java:87) ~[indexer.jar:2.0.0]
	at com.tesco.ess.indexer.services.CouchbaseAdmin.<init>(CouchbaseAdmin.java:46) ~[indexer.jar:2.0.0]
	at com.tesco.ess.indexer.CamelContextHelper.setupCouchbaseService(CamelContextHelper.java:104) ~[indexer.jar:2.0.0]
	at com.tesco.ess.indexer.IndexerRunner.<init>(IndexerRunner.java:45) [indexer.jar:2.0.0]
	at com.tesco.ess.indexer.IndexerRunner.main(IndexerRunner.java:32) [indexer.jar:2.0.0]
Caused by: java.util.concurrent.TimeoutException
	... 8 more

willpowell · July 12, 2019, 1:12pm

I have done a tcpdump of the traffic during this bug and have found that the client is never making a Get Cluster Config Request to the server.

For some reason, after the SASL Strep Response/Request/ACK, it is waiting 30 seconds then timing out, without ever sending the request.

Topic		Replies	Views
Couchbase connection time out with java sdk Java SDK	1	8570	July 24, 2015
Error while connecting containerized couchbase instance using Java-Client Java SDK java	2	2982	June 5, 2020
Bucket disconnected Java SDK	7	2746	June 19, 2020
Couchbase java client not reconnecting after connection timeout Java SDK	7	8320	October 30, 2017
Timeout for basic bucket query Java SDK	8	5445	June 29, 2015

Couchbase disconnecting from node immediately after creating bucket using java sdk

Related topics