Connection times to cluster

Java SDK
,
1

Hi all, I’m working on an application based on Spring framework (war application under tomcat that at some point needs to connect to a couchbase cluster (v. 7).
I’m using the latest version of the Java libraries for Couchbase and a standard Cluster.connect(url, username, password) code.
The weird behavior I’m experiencing is that when the application tries to connect to the cluster, it stays around 20 seconds hanging before connecting: no log (lowered to trace level), no messages from tomcat, nothing but hanging for 20+ seconds.
Same code line in a single main class from the same environment takes less than 200millis to connect.
I’ve tried with different ClusterEnvironment properties but same huge connection times.

So my question is; does someone have the same problem? Are there any incompatibilities between the libraries and Spring or tomcat?

2

Does it succeed after 20 seconds? It sounds like you are saying that it does.

With logging <logger name="com.couchbase" level="trace"/> , I see 174 lines of logging on a successful connect/disconnect, so I would expect to see quite a bit of logging.

Searching jira, I don’t find any issues matching your description.
https://issues.couchbase.com/issues/?jql=text%20~%20"tomcat%20connect"%20ORDER%20BY%20created%20DESC

It would be useful to see the TRACE log and also the code from both the standalone app and the tomcat app.

After connecting, can both apps execute kv operations? Query operations?
Are you running the two different apps from different hosts?
The client SDK will first try to get the configuration from the KV port, and if that fails, it will try to get the configuration from the mgmt port. I wonder if the standalone app is successfully getting it from the KV port, but the tomcat app is failing to get it from the kv port, but succeeding from the mgmt port.

4

yes, after about 20 seconds the connection succeeds and the we are able to get the document by key in few milliseconds.
yes, same host for both apps.
I’ve no trace log to show because the application hangs and it literally does nothing during that time, both in tomcat and application logs.

The code from the app and the stand alone is the same:
Cluster myCluster = Cluster.connect(“myurl”, user, pass);

I also tried from the same host to get the same document from the same bucket via curl and it succeeds in few milliseconds (like the stand alone class), so I think that it might be related to tomcat or Spring environment

5

I’ve no trace log to show because the application hangs and it literally does nothing during that time,

trace.zip (6.6 KB)

As I mentioned, when logging com.couchbase at TRACE, there are 174 lines of logging for a simple connect/disconnect. If you are not getting any logging, then your logging configuration is suspect. I’ve attached my log so you can see what it should look like.

SDK Doctor SDK Doctor | Couchbase Docs is also useful for diagnosing issues.

6

My logs at trace level are quite similar to yours.
At the end of my file, between line 37 and 38 there are 4secs and nothing logged.
Between 38 and 39 a lot of secs and no log and no activities.
Then the connection to the node succeeds and the document get is as expected.

I cannot upload (as a new user) but here is the log:

06/10/2022 15:25:13,301 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.logging.InternalLoggerFactory][RMI TCP Connection(3)-127.0.0.1] - Using SLF4J as the default logging framework
06/10/2022 15:25:13,311 DEBUG [com.couchbase.client.core.deps.io.netty.util.ResourceLeakDetector][RMI TCP Connection(3)-127.0.0.1] - -Dcom.couchbase.client.core.deps.io.netty.leakDetection.level: simple
06/10/2022 15:25:13,311 DEBUG [com.couchbase.client.core.deps.io.netty.util.ResourceLeakDetector][RMI TCP Connection(3)-127.0.0.1] - -Dcom.couchbase.client.core.deps.io.netty.leakDetection.targetRecords: 4
06/10/2022 15:25:13,315 DEBUG [com.couchbase.client.core.deps.io.netty.util.ResourceLeakDetectorFactory][RMI TCP Connection(3)-127.0.0.1] - Loaded default ResourceLeakDetector: com.couchbase.client.core.deps.io.netty.util.ResourceLeakDetector@30b3d8e7
06/10/2022 15:25:13,383 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.noUnsafe: false
06/10/2022 15:25:13,383 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - Java version: 8
06/10/2022 15:25:13,384 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - sun.misc.Unsafe.theUnsafe: available
06/10/2022 15:25:13,385 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - sun.misc.Unsafe.copyMemory: available
06/10/2022 15:25:13,386 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - sun.misc.Unsafe.storeFence: available
06/10/2022 15:25:13,386 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - java.nio.Buffer.address: available
06/10/2022 15:25:13,387 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - direct buffer constructor: available
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - java.nio.Bits.unaligned: available, true
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent0][RMI TCP Connection(3)-127.0.0.1] - java.nio.DirectByteBuffer.<init>(long, int): available
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - sun.misc.Unsafe: available
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.tmpdir: C:\Prg\Tomcat\apache-tomcat-8.5.65\temp (java.io.tmpdir)
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.bitMode: 64 (sun.arch.data.model)
06/10/2022 15:25:13,388 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - Platform: Windows
06/10/2022 15:25:13,390 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.maxDirectMemory: 3754426368 bytes
06/10/2022 15:25:13,390 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.uninitializedArrayAllocationThreshold: -1
06/10/2022 15:25:13,391 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.CleanerJava6][RMI TCP Connection(3)-127.0.0.1] - java.nio.ByteBuffer.cleaner(): available
06/10/2022 15:25:13,392 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.noPreferDirect: false
06/10/2022 15:25:13,577 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.PlatformDependent][RMI TCP Connection(3)-127.0.0.1] - com.couchbase.client.core.deps.org.jctools-core.MpscChunkedArrayQueue: available
06/10/2022 15:25:13,630 DEBUG [com.couchbase.client.core.deps.io.netty.channel.MultithreadEventLoopGroup][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.eventLoopThreads: 16
06/10/2022 15:25:13,669 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.InternalThreadLocalMap][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
06/10/2022 15:25:13,669 DEBUG [com.couchbase.client.core.deps.io.netty.util.internal.InternalThreadLocalMap][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
06/10/2022 15:25:13,684 DEBUG [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.noKeySetOptimization: false
06/10/2022 15:25:13,684 DEBUG [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - -Dio.netty.selectorAutoRebuildThreshold: 512
06/10/2022 15:25:13,690 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@58abfdcd
06/10/2022 15:25:13,692 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@665c68cc
06/10/2022 15:25:13,693 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@35bee411
06/10/2022 15:25:13,694 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@771e4b6d
06/10/2022 15:25:13,697 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@578fc78f
06/10/2022 15:25:13,699 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@1615a14a
06/10/2022 15:25:13,700 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@1acd8144
06/10/2022 15:25:13,701 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@33d79e2d
06/10/2022 15:25:13,702 TRACE [com.couchbase.client.core.deps.io.netty.channel.nio.NioEventLoop][RMI TCP Connection(3)-127.0.0.1] - instrumented a special java.util.Set into: sun.nio.ch.WindowsSelectorImpl@631d86dd
06/10/2022 15:25:18,155 DEBUG [com.couchbase.core][cb-events] - [com.couchbase.core][DnsSrvLookupDisabledEvent] DNS SRV lookup disabled (enabled on the env: false, valid host: true)
06/10/2022 15:26:14,893 DEBUG [com.couchbase.core][cb-events] - [com.couchbase.core][ReconfigurationCompletedEvent][17ms] Reconfiguration attempt completed. {"coreId":"0x77e1e2db00000001"}
06/10/2022 15:26:15,125 INFO  [com.couchbase.core][cb-events] - [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.3.1","clientGitHash":"${buildNumber}","coreVersion":"2.3.1","coreGitHash":"${buildNumber}","userAgent":"couchbase-java/3.3.1 (Windows 10 10.0 amd64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_291-b10)","maxNumRequestsInRetry":32768,"ioEnvironment":{"nativeIoEnabled":true,"eventLoopThreadCount":4,"eventLoopGroups":["NioEventLoopGroup"]},"ioConfig":{"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"tcpKeepAlivesEnabled":true,"tcpKeepAliveTimeMs":60000,"configPollIntervalMs":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled","eventingCircuitBreakerConfig":"disabled","backupCircuitBreakerConfig":"disabled","numKvConnections":1,"maxHttpConnections":12,"idleHttpConnectionTimeoutMs":4500,"configIdleRedialTimeoutMs":300000,"memcachedHashingStrategy":"StandardMemcachedHashingStrategy"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"hostnameVerificationEnabled":true,"trustCertificates":null,"trustManagerFactory":null,"ciphers":[]},"timeoutConfig":{"kvMs":2500,"kvDurableMs":10000,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000,"eventingMs":75000,"backupMs":75000},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"consoleLogLevel":{"name":"INFO","resourceBundleName":"sun.util.logging.resources.logging","localizedName":"INFORMAZIONI"},"consoleLoggerFormatter":"DefaultLoggerFormatter","disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"orphanReporterConfig":{"emitIntervalMs":10000,"sampleSize":10,"queueLength":1024,"enabled":true},"thresholdLoggingTracerConfig":{"enabled":true,"emitIntervalMs":10000,"sampleSize":10,"queueLength":1024,"kvThresholdMs":500,"queryThresholdMs":1000,"searchThresholdMs":1000,"analyticsThresholdMs":1000,"viewThresholdMs":1000},"loggingMeterConfig":{"enabled":true,"emitIntervalMs":600000},"retryStrategy":"BestEffortRetryStrategy","requestTracer":"ThresholdLoggingTracer","meter":"LoggingMeter","numRequestCallbacks":0,"scheduler":"ParallelScheduler","schedulerThreadCount":8,"transactionsConfig":{"durabilityLevel":"MAJORITY","timeoutMs":15000,"cleanupConfig":{"runLostAttemptsCleanupThread":true,"runRegularAttemptsCleanupThread":true,"cleanupWindowMs":60000,"cleanupSet":""},"numAtrs":1024,"metadataCollection":"none","scanConsistency":"none"}} {"coreId":"0x77e1e2db00000001","seedNodes":[{"address":"serveraddress.com"}]}
06/10/2022 15:26:15,125 DEBUG [com.couchbase.transactions.cleanup.regular][cb-events] - [com.couchbase.transactions.cleanup.regular][LogEvent] Starting background cleanup thread to find transactions from this client
06/10/2022 15:26:15,125 INFO  [com.couchbase.transactions][cb-events] - [com.couchbase.transactions][TransactionsStartedEvent] Transactions successfully initialised, regular cleanup enabled=true, lost cleanup enabled=true
06/10/2022 15:26:15,241 INFO  [com.couchbase.node][cb-events] - [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":"0x77e1e2db00000001","managerPort":"8091","remote":"serveraddress.com"}
7

56 seconds elapsed here. Right after the Couchbase SDK decides not use use DNS SRV. It could be a DNS lookup. A thread dump at this point would be useful. Also using the ip instead of hostname might shed some light on the problem.

06/10/2022 15:25:18,155 DEBUG [com.couchbase.core][cb-events] - [com.couchbase.core][DnsSrvLookupDisabledEvent] DNS SRV lookup disabled (enabled on the env: false, valid host: true)

06/10/2022 15:26:14,893 DEBUG [com.couchbase.core][cb-events] - [com.couchbase.core][ReconfigurationCompletedEvent][17ms] Reconfiguration attempt completed. {"coreId":"0x77e1e2db00000001"}
8

Also tried enabling DNS but same results.
I’ll try to dump of the threads and check it out.

9

EnableDNSSrv will leverage the usage of DNS SRV (service) records. This is not applicable for your case.

What happens when you use the ip address i atead of the.name?