I am trying to use Spring Data Couchbase to connect to Couchbase server using SSL certificates. I believe the certificate is configured correctly and can log in to the bucket using CertAuth but I am then seeing a strange ConnectTimeoutException.
In my application I am using Spring Data Couchbase (v 3.1.4RELEASE) to connect to my Couchbase 6.0 server, running on Mac OS. To configure the CouchbaseEnvironment I am overriding the AbstractCouchbaseConfiguration class to provide my own CouchbaseEnvironment bean definition:
@Override
@Bean(destroyMethod = "shutdown", name = BeanNames.COUCHBASE_ENV)
public CouchbaseEnvironment couchbaseEnvironment() {
CouchbaseEnvironment environment = DefaultCouchbaseEnvironment
.builder()
.sslEnabled(true)
.sslKeystoreFile("src/main/resources/third.keystore")
.sslKeystorePassword("storepass")
.certAuthEnabled(true)
.build();
return environment;
}
Also the cluster bean is defined as:
@Bean(destroyMethod = "disconnect", name = BeanNames.COUCHBASE_CLUSTER)
public Cluster couchbaseCluster() throws Exception {
Cluster cluster = CouchbaseCluster.create(couchbaseEnvironment(), getBootstrapHosts());
cluster.authenticate(CertAuthenticator.INSTANCE);
return cluster;
}
I have followed the instructions given here: https://docs.couchbase.com/server/6.0/manage/manage-security/configure-server-certificates.html to create the key/cert needed on the Couchbase server.
I then followed the instructions here: https://docs.couchbase.com/server/6.0/manage/manage-security/configure-client-certificates.html to configure the client side certificates, and create the Keystore. That keystore is the one mentioned in the above code.
The certificate contains a CN=<> which corresponds to the user created for the bucket on Couchbase server.
When I start up the application and it tries to get a connection to Couchbase and the bucket, I believe that works, because when I change the name of the user on Couchbase server to something different to what is in the CN= of the client certificate, I get exceptions stating that the login credentials are invalid. When I change the name of the user back to match whats in the cert, I do not see such exceptions.
However the problem then is that I see ConnectExceptions in the logs (full logs given below):
2019-02-05 09:36:06.869 WARN [-,,,] 91111 --- [tionScheduler-3] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Socket connect took longer than specified timeout: Connect callback did not return, hit safeguarding timeout.
2019-02-05 09:36:06.877 WARN [-,,,] 91111 --- [tionScheduler-3] c.couchbase.client.core.RequestHandler : Received Error during Reconfiguration.
com.couchbase.client.deps.io.netty.channel.ConnectTimeoutException: Connect callback did not return, hit safeguarding timeout.
at com.couchbase.client.core.endpoint.AbstractEndpoint$3.call(AbstractEndpoint.java:385) ~[core-io-1.7.2.jar:na]
at com.couchbase.client.core.endpoint.AbstractEndpoint$3.call(AbstractEndpoint.java:378) ~[core-io-1.7.2.jar:na]
at rx.internal.operators.SingleOperatorOnErrorResumeNext$2.onError(SingleOperatorOnErrorResumeNext.java:69) [rxjava-1.2.0.jar:1.2.0]
I have tried running couchbase both in Docker (configuring port forwards to all the ports I know about) and as an application running on my Mac, and the same thing happens in each case. I have also tried disabling the firewall on my machine and the same thing happens.
Any ideas why this is happening?
Full debug log of my Spring Boot app given here...
2019-02-12 10:24:55.730 DEBUG [-,,,] 89978 --- [-computations-2] com.couchbase.client.core.node.Node : [127.0.0.1/localhost]: Adding Service VIEW
2019-02-12 10:24:55.730 DEBUG [-,,,] 89978 --- [-computations-2] com.couchbase.client.core.node.Node : [127.0.0.1/localhost]: Service VIEW already added, skipping.
2019-02-12 10:24:55.741 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:11207][KeyValueEndpoint]: Channel Inactive.
2019-02-12 10:24:55.741 INFO [-,,,] 89978 --- [ cb-io-1-4] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Got notified from Channel as inactive, attempting reconnect.
2019-02-12 10:24:55.741 DEBUG [-,,,] 89978 --- [ cb-core-3-1] c.c.c.core.config.ConfigurationProvider : Received signal to proactively refresh (a maybe outdated) configuration.
2019-02-12 10:24:55.749 DEBUG [-,,,] 89978 --- [ cb-core-3-2] c.c.client.core.endpoint.Endpoint : Using a connectCallbackGracePeriod of 2000 on Endpoint localhost:18091
2019-02-12 10:24:55.946 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.core.endpoint.SSLEngineFactory : No TrustStore provided, using provided KeyStore to initialize both factories.
2019-02-12 10:24:55.953 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.client.core.endpoint.Endpoint : [localhost/127.0.0.1:18091][ConfigEndpoint]: Connected Endpoint.
2019-02-12 10:24:55.957 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:18091][ConfigEndpoint]: Channel Active.
2019-02-12 10:24:55.981 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.d.io.netty.handler.ssl.SslHandler : [id: 0xe5488f07, L:/127.0.0.1:64642 - R:localhost/127.0.0.1:18091] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
2019-02-12 10:24:55.987 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.client.core.endpoint.Endpoint : [localhost/127.0.0.1:18091][ConfigEndpoint]: Disconnected Endpoint.
2019-02-12 10:24:55.988 DEBUG [-,,,] 89978 --- [-computations-4] c.c.c.c.config.refresher.HttpRefresher : Successfully got config refresh from terse bucket remote.
2019-02-12 10:24:55.988 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:18091][ConfigEndpoint]: Channel Inactive.
2019-02-12 10:24:55.988 DEBUG [-,,,] 89978 --- [-computations-4] c.c.c.core.config.ConfigurationProvider : New Bucket payment_instruments config proposed.
2019-02-12 10:24:55.989 DEBUG [-,,,] 89978 --- [-computations-4] c.c.c.c.config.refresher.HttpRefresher : Completed refreshing config for bucket "payment_instruments"
2019-02-12 10:24:58.368 DEBUG [-,,,] 89978 --- [tionScheduler-3] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Endpoint connect completed, but got instructed to disconnect in the meantime.
2019-02-12 10:24:58.722 WARN [-,,,] 89978 --- [tionScheduler-3] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Socket connect took longer than specified timeout: Connect callback did not return, hit safeguarding timeout.
2019-02-12 10:24:58.724 WARN [-,,,] 89978 --- [tionScheduler-3] c.couchbase.client.core.RequestHandler : Received Error during Reconfiguration.
com.couchbase.client.deps.io.netty.channel.ConnectTimeoutException: Connect callback did not return, hit safeguarding timeout.
at com.couchbase.client.core.endpoint.AbstractEndpoint$3.call(AbstractEndpoint.java:385) ~[core-io-1.7.2.jar:na]
at com.couchbase.client.core.endpoint.AbstractEndpoint$3.call(AbstractEndpoint.java:378) ~[core-io-1.7.2.jar:na]
at rx.internal.operators.SingleOperatorOnErrorResumeNext$2.onError(SingleOperatorOnErrorResumeNext.java:69) [rxjava-1.2.0.jar:1.2.0]
at rx.Single$18.onError(Single.java:1891) [rxjava-1.2.0.jar:1.2.0]
at rx.observers.SafeSubscriber._onError(SafeSubscriber.java:152) [rxjava-1.2.0.jar:1.2.0]
at rx.observers.SafeSubscriber.onError(SafeSubscriber.java:115) [rxjava-1.2.0.jar:1.2.0]
at rx.observers.SerializedObserver.onError(SerializedObserver.java:153) [rxjava-1.2.0.jar:1.2.0]
at rx.observers.SerializedSubscriber.onError(SerializedSubscriber.java:78) [rxjava-1.2.0.jar:1.2.0]
at rx.internal.operators.OperatorTimeoutBase$TimeoutSubscriber$1.onError(OperatorTimeoutBase.java:187) [rxjava-1.2.0.jar:1.2.0]
at rx.Single$1$1.onError(Single.java:84) [rxjava-1.2.0.jar:1.2.0]
at rx.Single$3.call(Single.java:492) [rxjava-1.2.0.jar:1.2.0]
at rx.Single$3.call(Single.java:488) [rxjava-1.2.0.jar:1.2.0]
at rx.Single$1.call(Single.java:89) [rxjava-1.2.0.jar:1.2.0]
at rx.Single$1.call(Single.java:69) [rxjava-1.2.0.jar:1.2.0]
at rx.Observable.unsafeSubscribe(Observable.java:10151) [rxjava-1.2.0.jar:1.2.0]
at rx.internal.operators.OperatorTimeoutBase$TimeoutSubscriber.onTimeout(OperatorTimeoutBase.java:200) [rxjava-1.2.0.jar:1.2.0]
at rx.internal.operators.OperatorTimeout$1$1.call(OperatorTimeout.java:41) [rxjava-1.2.0.jar:1.2.0]
at rx.internal.schedulers.EventLoopsScheduler$EventLoopWorker$2.call(EventLoopsScheduler.java:189) [rxjava-1.2.0.jar:1.2.0]
at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) [rxjava-1.2.0.jar:1.2.0]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_181]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_181]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_181]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_181]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
2019-02-12 10:24:58.727 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.core.endpoint.SSLEngineFactory : No TrustStore provided, using provided KeyStore to initialize both factories.
2019-02-12 10:24:58.730 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.c.e.kv.KeyValueFeatureHandler : Requesting supported features: [TCPNODELAY, XATTR, SELECT_BUCKET, TRACING, SNAPPY, XERROR]
2019-02-12 10:24:58.741 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:11207][KeyValueEndpoint]: Channel Inactive.
2019-02-12 10:24:58.741 INFO [-,,,] 89978 --- [ cb-io-1-4] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Got notified from Channel as inactive, attempting reconnect.
2019-02-12 10:24:58.741 DEBUG [-,,,] 89978 --- [ cb-core-3-1] c.c.c.core.config.ConfigurationProvider : Received signal to proactively refresh (a maybe outdated) configuration.
2019-02-12 10:24:58.756 DEBUG [-,,,] 89978 --- [ cb-core-3-2] c.c.client.core.endpoint.Endpoint : Using a connectCallbackGracePeriod of 2000 on Endpoint localhost:18091
2019-02-12 10:24:58.758 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.core.endpoint.SSLEngineFactory : No TrustStore provided, using provided KeyStore to initialize both factories.
2019-02-12 10:24:58.759 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.client.core.endpoint.Endpoint : [localhost/127.0.0.1:18091][ConfigEndpoint]: Connected Endpoint.
2019-02-12 10:24:58.761 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:18091][ConfigEndpoint]: Channel Active.
2019-02-12 10:24:58.780 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.d.io.netty.handler.ssl.SslHandler : [id: 0x2c530df7, L:/127.0.0.1:64655 - R:localhost/127.0.0.1:18091] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
2019-02-12 10:24:58.783 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.client.core.endpoint.Endpoint : [localhost/127.0.0.1:18091][ConfigEndpoint]: Disconnected Endpoint.
2019-02-12 10:24:58.783 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:18091][ConfigEndpoint]: Channel Inactive.
2019-02-12 10:24:58.784 DEBUG [-,e59439f67cd93cb5,e59439f67cd93cb5,true] 89978 --- [-computations-4] c.c.c.c.config.refresher.HttpRefresher : Successfully got config refresh from terse bucket remote.
2019-02-12 10:24:58.784 DEBUG [-,e59439f67cd93cb5,e59439f67cd93cb5,true] 89978 --- [-computations-4] c.c.c.core.config.ConfigurationProvider : New Bucket payment_instruments config proposed.
2019-02-12 10:24:58.785 DEBUG [-,e59439f67cd93cb5,e59439f67cd93cb5,true] 89978 --- [-computations-4] c.c.c.c.config.refresher.HttpRefresher : Completed refreshing config for bucket "payment_instruments"
2019-02-12 10:25:01.730 WARN [-,,,] 89978 --- [tionScheduler-1] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Socket connect took longer than specified timeout: Connect callback did not return, hit safeguarding timeout.
2019-02-12 10:25:01.731 WARN [-,,,] 89978 --- [tionScheduler-1] c.c.client.core.endpoint.Endpoint : Error during reconnect: com.couchbase.client.deps.io.netty.channel.ConnectTimeoutException: Connect callback did not return, hit safeguarding timeout.
2019-02-12 10:25:01.731 WARN [-,,,] 89978 --- [tionScheduler-1] c.c.client.core.endpoint.Endpoint : [localhost:11207][KeyValueEndpoint]: Could not connect to endpoint on reconnect attempt 2, retrying with delay 32 MILLISECONDS: com.couchbase.client.deps.io.netty.channel.ConnectTimeoutException: Connect callback did not return, hit safeguarding timeout.
2019-02-12 10:25:01.731 DEBUG [-,,,] 89978 --- [ cb-core-3-1] c.c.c.core.config.ConfigurationProvider : Received signal to proactively refresh (a maybe outdated) configuration.
2019-02-12 10:25:01.732 DEBUG [-,,,] 89978 --- [ cb-core-3-2] c.c.client.core.endpoint.Endpoint : Using a connectCallbackGracePeriod of 2000 on Endpoint localhost:18091
2019-02-12 10:25:01.734 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.core.endpoint.SSLEngineFactory : No TrustStore provided, using provided KeyStore to initialize both factories.
2019-02-12 10:25:01.736 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.client.core.endpoint.Endpoint : [localhost/127.0.0.1:18091][ConfigEndpoint]: Connected Endpoint.
2019-02-12 10:25:01.739 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:18091][ConfigEndpoint]: Channel Active.
2019-02-12 10:25:01.761 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.d.io.netty.handler.ssl.SslHandler : [id: 0x6c94cdd6, L:/127.0.0.1:64667 - R:localhost/127.0.0.1:18091] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
2019-02-12 10:25:01.764 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.client.core.endpoint.Endpoint : [localhost/127.0.0.1:18091][ConfigEndpoint]: Disconnected Endpoint.
2019-02-12 10:25:01.764 DEBUG [-,,,] 89978 --- [ cb-io-1-4] c.c.c.c.endpoint.AbstractGenericHandler : [localhost/127.0.0.1:18091][ConfigEndpoint]: Channel Inactive.
2019-02-12 10:25:01.764 DEBUG [-,f18dfda57f4b39ba,f18dfda57f4b39ba,true] 89978 --- [-computations-4] c.c.c.c.config.refresher.HttpRefresher : Successfully got config refresh from terse bucket remote.
2019-02-12 10:25:01.765 DEBUG [-,f18dfda57f4b39ba,f18dfda57f4b39ba,true] 89978 --- [-computations-4] c.c.c.core.config.ConfigurationProvider : New Bucket payment_instruments config proposed.
2019-02-12 10:25:01.765 DEBUG [-,f18dfda57f4b39ba,f18dfda57f4b39ba,true] 89978 --- [-computations-4] c.c.c.c.config.refresher.HttpRefresher : Completed refreshing config for bucket "payment_instruments"
2019-02-12 10:25:01.765 DEBUG [-,,,] 89978 --- [ cb-io-1-1] c.c.c.core.endpoint.SSLEngineFactory : No TrustStore provided, using provided KeyStore to initialize both factories.
