Maybe a Bolt issue

[sergio-nunez-meneses-davi]

Hi everyone, newbie web developer and Neo4j user here.

We're facing an issue with Neo4j Community Edition hosted in Azure. We've developed an API that uses Laudis Neo4j PHP Client and Bolt library.

When using the API in local development, for instance, through Postman, everything works perfect. But when using the API hosted in Azure, we get HTTP status code 500 most of the time. When performing queries used in the API in Neo4j Browser, it also works.

Inspecting the debug.log file, we've found these errors and warnings:

2021-09-01 02:09:13.893+0000 ERROR [o.n.b.t.p.ProtocolHandshaker] Fatal error occurred during protocol handshaking: [id: 0x9582075a, L:/10.0.0.1:7687 - R:/123.456.789.12:34294]
java.lang.SecurityException: An unencrypted connection attempt was made where encryption is required.
    at org.neo4j.bolt.transport.pipeline.ProtocolHandshaker.assertEncryptedIfRequired(ProtocolHandshaker.java:151) ~[neo4j-bolt-4.2.6.jar:4.2.6]
    at org.neo4j.bolt.transport.pipeline.ProtocolHandshaker.channelRead(ProtocolHandshaker.java:89) ~[neo4j-bolt-4.2.6.jar:4.2.6]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:253) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:515) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at org.neo4j.bolt.transport.pipeline.AuthenticationTimeoutTracker.channelRead(AuthenticationTimeoutTracker.java:45) [neo4j-bolt-4.2.6.jar:4.2.6]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:480) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.63.Final.jar:4.1.63.Final]
    at java.lang.Thread.run(Thread.java:829) [?:?]
2021-09-01 02:09:14.246+0000 DEBUG [i.n.h.s.SslHandler] [id: 0xbe948ddf, L:/10.0.0.1:7687 - R:/123.456.789.12:34294] HANDSHAKEN: protocol:TLSv1.2 cipher suite:TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2021-09-01 02:09:14.344+0000 DEBUG [o.n.b.t.p.ProtocolHandshaker] Failed Bolt handshake: Bolt versions suggested by client '[org.neo4j.bolt.BoltProtocolVersion@3c2, org.neo4j.bolt.BoltProtocolVersion@3c1, org.neo4j.bolt.BoltProtocolVersion@3c1, org.neo4j.bolt.BoltProtocolVersion@3c1]' are not supported by this server.
2021-09-01 02:24:19.249+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1484, gcTime=0, gcCount=0}
2021-09-01 02:46:03.915+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1499, gcTime=0, gcCount=0}
2021-09-01 04:07:37.441+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1483, gcTime=1484, gcCount=2}
2021-09-01 06:07:34.077+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1492, gcTime=0, gcCount=0}

2021-09-01 08:00:08.712+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1490, gcTime=1511, gcCount=2}
2021-09-01 08:00:10.276+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1463, gcTime=1505, gcCount=3}
2021-09-01 08:00:11.833+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1456, gcTime=1502, gcCount=2}
2021-09-01 08:00:13.387+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1454, gcTime=1506, gcCount=2}
2021-09-01 08:00:14.938+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1451, gcTime=1510, gcCount=2}
2021-09-01 08:00:16.480+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1441, gcTime=1503, gcCount=2}
2021-09-01 08:00:18.040+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1460, gcTime=1522, gcCount=2}
2021-09-01 08:00:19.582+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1441, gcTime=1506, gcCount=2}
2021-09-01 08:00:21.127+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1445, gcTime=1511, gcCount=2}
2021-09-01 08:00:22.690+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1462, gcTime=1514, gcCount=2}
2021-09-01 08:03:19.453+0000 WARN  [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1450, gcTime=1497, gcCount=2}

Moreover, looking at the server logs, we've found exceptions:

2021-09-07 13:43:54 Error   01.234.567.890  500 GET /endpoint?params HTTP/1.0       Symfony HttpClient/Curl 342     Accès SSL/TLS Apache
2021-09-07 13:44:09 Error   01.234.567.890  AH01071: Got error 'PHP message: PHP Fatal error: Uncaught Bolt\\error\\ConnectException: Read error in /vendor/stefanak-michal/bolt/src/connection/StreamSocket.php:102\nStack trace:\n#0 /vendor/stefanak-michal/bolt/src/protocol/AProtocol.php(94): Bolt\\connection\\StreamSocket->read()\n#1 /vendor/stefanak-michal/bolt/src/protocol/V3.php(72): Bolt\\protocol\\AProtocol->read()\n#2 /vendor/stefanak-michal/bolt/src/Bolt.php(262): Bolt\\protocol\\V3->run()\n#3 /vendor/laudis/neo4j-php-client/src/Bolt/BoltUnmanagedTransaction.php(121): Bolt\\Bolt->run()\n#4 /vendor/laudis/neo4j-php-client/src/Bolt/Session.php(77): Laudis\\Neo4...'               Erreur Apache
2021-09-07 19:11:16 Error   012.34.567.89   400 GET / HTTP/1.0

We've updated both repositories' versions, but it didn't help.

Would anyone have an idea on how to solve this?

Please let me know if I didn't post this issue in the correct repository. Thank you very much in advance !

[stefanak-michal]

Hi @sergio-nunez-meneses-davi .

I would like to see your code where you create connection.

Because what is strange for me, you are speaking about API but at the end error is Bolt protocol. API and Bolt are two things. Bolt is low level socket protocol used for communication while API is HTTP endpoint.

But in the error I see message "read error" which can mean you have wrong connection configuration. Therefore I'm asking for piece of code how you are creating connection.

[sergio-nunez-meneses-davi]

Hi @stefanak-michal ,

Thank you for your quick reply, and I'm sorry for the misunderstanding.

Here's the requested connection:

public function __construct() {
    $this->client = ClientBuilder::create()
            ->withDriver('bolt',
                         sprintf('%s://%s:%s@%s:7687', DB_PROTOCOL, DB_USER, DB_PASSWORD, DB_HOST))
            ->withDefaultDriver('bolt')
            ->build();
}

Thank you again for your help.

[stefanak-michal]

I'm going through your error a there is message about secure connection.

You have to tell the Bolt to use SSL. @transistive has implemented this and you can read about it here: https://github.com/neo4j-php/neo4j-php-client/wiki/Configuring-connections#bolt-configuration

Also you can check for more informations https://github.com/neo4j-php/Bolt/wiki/Connection#boltconnectionstreamsocket

That means you have to extend your code like this (not tested):

public function __construct() {
    $this->client = ClientBuilder::create()
            ->withDriver(
                                     'bolt',
                         sprintf('%s://%s:%s@%s:7687', DB_PROTOCOL, DB_USER, DB_PASSWORD, DB_HOST),
                                     BoltConfig::create()->withSslContextOptions(['verify_peer' => true])
                        )
            ->withDefaultDriver('bolt')
            ->build();
}

[sergio-nunez-meneses-davi]

Hi @stefanak-michal,

Thank you very much for your suggestion. Unfortunately, the method withDriver() doesn't allow BoltConfiguration as an argument. The previous method, addBoltConnection(), did it.

AH01071: Got error 'PHP message: PHP Fatal error: Uncaught TypeError: Argument 3 passed to Laudis\\Neo4j\\ClientBuilder::withDriver() must be an instance of Laudis\\Neo4j\\Contracts\\AuthenticateInterface or null

Do you or @transistive know how to implement this in the newer version? Thank you both again.

[stefanak-michal]

I'm not very familiar with @transistive library. But maybe if you use different protocol to enable SSL for Bolt. What is content of DB_PROTOCOL? Maybe if you try bolt+s?

[transistive]

Hi everyone!

Thank you, Michal, for bringing the wiki to my attention. It is out of date. You are supposed to use the bolt+s or neo4j+s scheme now. I think @sergio-nunez-meneses-davi already tried this. Have you had the time to try the HTTPS scheme?

If it still does not work, it might be best to schedule a call to look at the issue. As far as I am aware, SSL does work as we use it with the driver and neo4j aura.

Thanks in advance,

Ghlen

[sergio-nunez-meneses-davi]

Good news!

I just solved the problem by enabling the GC Logging in the neo4j.conf file. Now everything works as expected, with both of your libraries up-to-date.

Thank you @transistive and @stefanak-michal for taking the time to answer and suggest solutions.

(By the way, DB_PROTOCOL is exactly bolt+s)

[transistive]

Perfect! bolt+s is the preferred scheme when using a single neo4j instance over the internet! Happy graphing!