Unable to establish connection in 5000ms errors

[amadfida]

Driver version: 1.5.0 (sync API)
Neo4j server : 3.3.1

After upgrade tp 1.5.0 we started to notice a lot of Unable to establish connection in 5000ms errors when server is busy - is 5s not enough to create connections ?

On client side we get

Caused by: org.neo4j.driver.v1.exceptions.ServiceUnavailableException: Unable to establish connection in 5000ms
	at org.neo4j.driver.internal.async.inbound.ConnectTimeoutHandler.unableToConnectError(ConnectTimeoutHandler.java:56)
	at org.neo4j.driver.internal.async.inbound.ConnectTimeoutHandler.readTimedOut(ConnectTimeoutHandler.java:50)
	at org.neo4j.driver.internal.shaded.io.netty.handler.timeout.ReadTimeoutHandler.channelIdle(ReadTimeoutHandler.java:90)
	at org.neo4j.driver.internal.shaded.io.netty.handler.timeout.IdleStateHandler$ReaderIdleTimeoutTask.run(IdleStateHandler.java:494)
	at org.neo4j.driver.internal.shaded.io.netty.handler.timeout.IdleStateHandler$AbstractIdleTask.run(IdleStateHandler.java:466)
	at org.neo4j.driver.internal.shaded.io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38)
	at org.neo4j.driver.internal.shaded.io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:120)
	at org.neo4j.driver.internal.shaded.io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
	at org.neo4j.driver.internal.shaded.io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
	at org.neo4j.driver.internal.shaded.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:463)
	at org.neo4j.driver.internal.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at org.neo4j.driver.internal.shaded.io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	... 1 more

on server side

2018-01-14 00:18:28.094+0000 WARN [io.netty.channel.DefaultChannelPipeline] An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception. javax.net.ssl.SSLException: Received close_notify during handshake
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received close_notify during handshake
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:459)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:236)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:494)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:801)
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Thread.java:748)
Caused by: javax.net.ssl.SSLException: Received close_notify during handshake
	at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1634)
	at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1776)
	at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1083)
	at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
	at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
	at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
	at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:292)
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1247)
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1158)
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1193)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
	... 20 more

[amadfida]

Though this same setting exists in 4.5.x version, however this error doesn't occur.

[lutovich]

Hi @amadfida,

Thanks for reporting this problem. Driver 1.5+ is a bit more strict about the connection timeout than 1.4 series.
Previous versions used the configured value only when establishing the actual socket connection. Basically as socket.connect(configuredConnectionTimeout). However, from driver's point of view establishing a connection includes:

1. establish a socket connection
2. perform SSL handshake, when encryption is enabled
3. perform Bolt protocol handshake
4. send an INIT message containing AuthToken and receive response for it

Driver 1.5+ enforces configured connection timeout on all these four steps instead of just on the first one.

Does this problem go away when you configure connection timeout to a slightly higher value? This can be done in a ConfigBuilder:

Config config = Config.build()
      .withConnectionTimeout( 10, TimeUnit.SECONDS )
      .toConfig()

Maybe we it's better to bump the default timeout value, since it now restricts more things.

[lutovich]

We decided to make the timeout include all those 4 things because otherwise driver could hang, when connecting to something that accepts connections but never responds.

[amadfida]

@lutovich our current grails plugin version doesn't support passing params to config but we are working on a newer version that will - so will need to test and verify.

[lutovich]

Thanks @amadfida, we'll wait for your feedback before doing any code changes.

[zhenlineo]

Hi @amadfida,

Have you get time to test out if it is helpful to pass a longer timeout? Since we have not receive any updates from you since the end of Jan, we consider your issue got solved. Please be free to open this issue again if the problem still exists.

Cheers,
Zhen

[pulkit96]

Hello even I am facing the same issue, I did bump the connection timeout of the driver to 10 seconds as suggested by @lutovich but the error still persists.
Neo4j Version: 3.3.2
Java Driver Version: 1.6.3
Neo4j Server Logs
2020-04-06 10:25:22.532+0000 WARN [io.netty.channel.DefaultChannelPipeline] An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception. javax.net.ssl.SSLException: Received close_notify during handshake io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received close_notify during handshake at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:459) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:236) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:494) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935) at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:801) at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) at java.lang.Thread.run(Thread.java:748) Caused by: javax.net.ssl.SSLException: Received close_notify during handshake at sun.security.ssl.Alerts.getSSLException(Alerts.java:208) at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1647) at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1615) at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1757) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1070) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:896) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:766) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:292)

Application Side:
It sometimes fails with
org.neo4j.driver.v1.exceptions.ServiceUnavailableException: Unable to establish connection in 5000ms
and sometimes with
Unable to acquire connection from the pool within configured maximum time of 60000ms] with root cause org.neo4j.driver.v1.exceptions.ClientException: Unable to acquire connection from the pool within configured maximum time of 60000ms

Any help would be appreciated.

[zhenlineo]

@pulkit96
Do you know how long it takes to establish a ssl connection in your network?

The error Unable to establish connection in 5000ms indicates that the driver has failed to establish a ssl connection with the server in 5s.
Then this one Unable to acquire connection from the pool within configured maximum time of 60000ms could caused by 1) failure to establish connection within timeout and/or 2) driver pool is full and the driver times out to wait for a free connection within timeout. If your pool is full, then you shall consider enlarging the pool size.

Also you could upgrade your driver to 1.7 drivers. It contains newest bug fixes and it is fully compatible with 3.3 servers. If your problem still persists after you tried all above suggestions, could you restart a new issue with descriptions that you think could help us reproduce your error?

[pulkit96]

@zhenlineo thanks for the prompt reply.
Do you know how long it takes to establish a ssl connection in your network?
Unfortunately, I am not aware of that. I'll try to find out.

I have tried increasing the connection pool size but it still fails so I am guessing it's the more of the first one where it fails to establish a connection within the timeout.
Also, I am using the spring-data-neo4j version (5.1.8) in my application which internally uses neo4j java driver 1.6.3.
On checking the spring-data-neo4j releases I could see that they have skipped the 1.7 version of the driver and moved straight to 4.x version in their 5.2.x releases.
Even moving to 5.2.x version will require quite a lot of effort in the migration and testing.
Let me know what can be done here.

Thanks