ConnectTimeoutException when trying to connect to Couchbase bucket from Spring Data Couchbase using SSL


#1

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.