Include database connection ID in debug logs

driver/src/main/java/org/neo4j/driver/internal/async/ChannelAttributes.java

@@ -29,6 +29,7 @@
 
 public final class ChannelAttributes
 {
+    private static final AttributeKey<String> CONNECTION_ID = newInstance( "connectionId" );
     private static final AttributeKey<Integer> PROTOCOL_VERSION = newInstance( "protocolVersion" );
     private static final AttributeKey<BoltServerAddress> ADDRESS = newInstance( "serverAddress" );
     private static final AttributeKey<ServerVersion> SERVER_VERSION = newInstance( "serverVersion" );
@@ -41,6 +42,16 @@ private ChannelAttributes()
     {
     }
 
+    public static String connectionId( Channel channel )
+    {
+        return get( channel, CONNECTION_ID );
+    }
+
+    public static void setConnectionId( Channel channel, String id )
+    {
+        setOnce( channel, CONNECTION_ID, id );
+    }
+
     public static int protocolVersion( Channel channel )
     {
         return get( channel, PROTOCOL_VERSION );

driver/src/main/java/org/neo4j/driver/internal/async/pool/NettyChannelTracker.java

@@ -62,7 +62,7 @@ public NettyChannelTracker( MetricsListener metricsListener, ChannelGroup channe
     @Override
     public void channelReleased( Channel channel )
     {
-        log.debug( "Channel %s released back to the pool", channel );
+        log.debug( "Channel [%s] released back to the pool", channel.id() );
         decrementInUse( channel );
         incrementIdle( channel );
         channel.closeFuture().addListener( closeListener );
@@ -71,7 +71,9 @@ public void channelReleased( Channel channel )
     @Override
     public void channelAcquired( Channel channel )
     {
-        log.debug( "Channel %s acquired from the pool", channel );
+        log.debug( "Channel [%s] acquired from the pool. Local address: %s, remote address: %s",
+                channel.id(), channel.localAddress(), channel.remoteAddress() );
+
         incrementInUse( channel );
         decrementIdle( channel );
         channel.closeFuture().removeListener( closeListener );
@@ -85,7 +87,9 @@ public void channelCreated( Channel channel )
 
     public void channelCreated( Channel channel, ListenerEvent creatingEvent )
     {
-        log.debug( "Channel %s created", channel );
+        log.debug( "Channel [%s] created. Local address: %s, remote address: %s",
+                channel.id(), channel.localAddress(), channel.remoteAddress() );
+
         incrementInUse( channel );
         metricsListener.afterCreated( serverAddress( channel ), creatingEvent );
 

driver/src/main/java/org/neo4j/driver/internal/handlers/HelloResponseHandler.java

@@ -27,10 +27,14 @@
 import org.neo4j.driver.internal.util.ServerVersion;
 import org.neo4j.driver.v1.Value;
 
+import static org.neo4j.driver.internal.async.ChannelAttributes.setConnectionId;
 import static org.neo4j.driver.internal.async.ChannelAttributes.setServerVersion;
 
 public class HelloResponseHandler implements ResponseHandler
 {
+    private static final String SERVER_METADATA_KEY = "server";
+    private static final String CONNECTION_ID_METADATA_KEY = "connection_id";
+
     private final ChannelPromise connectionInitializedPromise;
     private final Channel channel;
 
@@ -45,8 +49,12 @@ public void onSuccess( Map<String,Value> metadata )
     {
         try
         {
-            ServerVersion serverVersion = extractServerVersion( metadata );
+            ServerVersion serverVersion = ServerVersion.version( extractMetadataValue( SERVER_METADATA_KEY, metadata ) );
             setServerVersion( channel, serverVersion );
+
+            String connectionId = extractMetadataValue( CONNECTION_ID_METADATA_KEY, metadata );
+            setConnectionId( channel, connectionId );
+
             connectionInitializedPromise.setSuccess();
         }
         catch ( Throwable error )
@@ -68,13 +76,13 @@ public void onRecord( Value[] fields )
         throw new UnsupportedOperationException();
     }
 
-    private static ServerVersion extractServerVersion( Map<String,Value> metadata )
+    private static String extractMetadataValue( String key, Map<String,Value> metadata )
     {
-        Value versionValue = metadata.get( "server" );
-        if ( versionValue == null || versionValue.isNull() )
+        Value value = metadata.get( key );
+        if ( value == null || value.isNull() )
         {
-            throw new IllegalStateException( "Unable to get server version from a response to HELLO message. Metadata: " + metadata );
+            throw new IllegalStateException( "Unable to extract " + key + " from a response to HELLO message. Metadata: " + metadata );
         }
-        return ServerVersion.version( versionValue.asString() );
+        return value.asString();
     }
 }

driver/src/main/java/org/neo4j/driver/internal/logging/ChannelActivityLogger.java

@@ -20,6 +20,7 @@
 
 import io.netty.channel.Channel;
 
+import org.neo4j.driver.internal.async.ChannelAttributes;
 import org.neo4j.driver.v1.Logger;
 import org.neo4j.driver.v1.Logging;
 
@@ -28,6 +29,9 @@
 public class ChannelActivityLogger extends ReformattedLogger
 {
     private final Channel channel;
+    private final String localChannelId;
+
+    private String dbConnectionId;
 
     public ChannelActivityLogger( Channel channel, Logging logging, Class<?> owner )
     {
@@ -38,6 +42,7 @@ private ChannelActivityLogger( Channel channel, Logger delegate )
     {
         super( delegate );
         this.channel = channel;
+        this.localChannelId = channel != null ? channel.id().toString() : null;
     }
 
     @Override
@@ -47,6 +52,22 @@ protected String reformat( String message )
         {
             return message;
         }
-        return format( "[0x%s] %s", channel.id(), message );
+
+        String dbConnectionId = getDbConnectionId();
+
+        if ( localChannelId != null && dbConnectionId != null )
+        {
+            return format( "[0x%s][%s] %s", localChannelId, dbConnectionId, message );
+        }
+        return format( "[0x%s][] %s", localChannelId, message );
+    }
+
+    private String getDbConnectionId()
+    {
+        if ( dbConnectionId == null )
+        {
+            dbConnectionId = ChannelAttributes.connectionId( channel );
+        }
+        return dbConnectionId;
     }
 }

driver/src/test/java/org/neo4j/driver/internal/DirectDriverBoltKitTest.java

@@ -0,0 +1,132 @@
+/*
+ * Copyright (c) 2002-2018 "Neo4j,"
+ * Neo4j Sweden AB [http://neo4j.com]
+ *
+ * This file is part of Neo4j.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.neo4j.driver.internal;
+
+import org.junit.jupiter.api.Test;
+import org.mockito.ArgumentCaptor;
+
+import java.net.URI;
+import java.util.List;
+import java.util.Optional;
+
+import org.neo4j.driver.v1.Config;
+import org.neo4j.driver.v1.Driver;
+import org.neo4j.driver.v1.GraphDatabase;
+import org.neo4j.driver.v1.Logger;
+import org.neo4j.driver.v1.Record;
+import org.neo4j.driver.v1.Session;
+import org.neo4j.driver.v1.Transaction;
+import org.neo4j.driver.v1.util.StubServer;
+
+import static java.util.Arrays.asList;
+import static org.hamcrest.core.IsEqual.equalTo;
+import static org.hamcrest.junit.MatcherAssert.assertThat;
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.atLeastOnce;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
+import static org.neo4j.driver.v1.Values.parameters;
+import static org.neo4j.driver.v1.util.StubServer.INSECURE_CONFIG;
+
+class DirectDriverBoltKitTest
+{
+    @Test
+    void shouldBeAbleRunCypher() throws Exception
+    {
+        StubServer server = StubServer.start( "return_x.script", 9001 );
+        URI uri = URI.create( "bolt://127.0.0.1:9001" );
+        int x;
+
+        try ( Driver driver = GraphDatabase.driver( uri, INSECURE_CONFIG ) )
+        {
+            try ( Session session = driver.session() )
+            {
+                Record record = session.run( "RETURN {x}", parameters( "x", 1 ) ).single();
+                x = record.get( 0 ).asInt();
+            }
+        }
+
+        assertThat( x, equalTo( 1 ) );
+        assertThat( server.exitStatus(), equalTo( 0 ) );
+    }
+
+    @Test
+    void shouldSendMultipleBookmarks() throws Exception
+    {
+        StubServer server = StubServer.start( "multiple_bookmarks.script", 9001 );
+
+        List<String> bookmarks = asList( "neo4j:bookmark:v1:tx5", "neo4j:bookmark:v1:tx29",
+                "neo4j:bookmark:v1:tx94", "neo4j:bookmark:v1:tx56", "neo4j:bookmark:v1:tx16",
+                "neo4j:bookmark:v1:tx68" );
+
+        try ( Driver driver = GraphDatabase.driver( "bolt://localhost:9001", INSECURE_CONFIG );
+              Session session = driver.session( bookmarks ) )
+        {
+            try ( Transaction tx = session.beginTransaction() )
+            {
+                tx.run( "CREATE (n {name:'Bob'})" );
+                tx.success();
+            }
+
+            assertEquals( "neo4j:bookmark:v1:tx95", session.lastBookmark() );
+        }
+        finally
+        {
+            assertEquals( 0, server.exitStatus() );
+        }
+    }
+
+    @Test
+    void shouldLogConnectionIdInDebugMode() throws Exception
+    {
+        StubServer server = StubServer.start( "hello_run_exit.script", 9001 );
+
+        Logger logger = mock( Logger.class );
+        when( logger.isDebugEnabled() ).thenReturn( true );
+
+        Config config = Config.build()
+                .withLogging( ignore -> logger )
+                .withoutEncryption().toConfig();
+
+        try ( Driver driver = GraphDatabase.driver( "bolt://localhost:9001", config );
+              Session session = driver.session() )
+        {
+            List<String> names = session.run( "MATCH (n) RETURN n.name" ).list( record -> record.get( 0 ).asString() );
+            assertEquals( asList( "Foo", "Bar" ), names );
+
+            ArgumentCaptor<String> messageCaptor = ArgumentCaptor.forClass( String.class );
+            verify( logger, atLeastOnce() ).debug( messageCaptor.capture(), any() );
+
+            Optional<String> logMessageWithConnectionId = messageCaptor.getAllValues()
+                    .stream()
+                    .filter( line -> line.contains( "bolt-123456789" ) )
+                    .findAny();
+
+            assertTrue( logMessageWithConnectionId.isPresent(),
+                    "Expected log call did not happen. All debug log calls:\n" + String.join( "\n", messageCaptor.getAllValues() ) );
+        }
+        finally
+        {
+            assertEquals( 0, server.exitStatus() );
+        }
+    }
+}

driver/src/test/java/org/neo4j/driver/internal/DirectDriverIT.java

@@ -24,30 +24,22 @@
 import org.junit.jupiter.api.extension.RegisterExtension;
 
 import java.net.URI;
-import java.util.Arrays;
-import java.util.List;
 
 import org.neo4j.driver.internal.util.EnabledOnNeo4jWith;
 import org.neo4j.driver.v1.Driver;
 import org.neo4j.driver.v1.GraphDatabase;
-import org.neo4j.driver.v1.Record;
 import org.neo4j.driver.v1.Session;
 import org.neo4j.driver.v1.StatementResult;
-import org.neo4j.driver.v1.Transaction;
 import org.neo4j.driver.v1.util.DatabaseExtension;
-import org.neo4j.driver.v1.util.StubServer;
 
 import static org.hamcrest.Matchers.is;
 import static org.hamcrest.core.IsEqual.equalTo;
 import static org.hamcrest.junit.MatcherAssert.assertThat;
-import static org.junit.jupiter.api.Assertions.assertEquals;
 import static org.junit.jupiter.api.Assertions.assertThrows;
 import static org.neo4j.driver.internal.BoltServerAddress.LOCAL_DEFAULT;
 import static org.neo4j.driver.internal.util.Matchers.directDriverWithAddress;
 import static org.neo4j.driver.internal.util.Neo4jFeature.CONNECTOR_LISTEN_ADDRESS_CONFIGURATION;
-import static org.neo4j.driver.v1.Values.parameters;
 import static org.neo4j.driver.v1.util.Neo4jRunner.DEFAULT_AUTH_TOKEN;
-import static org.neo4j.driver.v1.util.StubServer.INSECURE_CONFIG;
 
 class DirectDriverIT
 {
@@ -118,57 +110,6 @@ void shouldRegisterSingleServer()
         assertThat( driver, is( directDriverWithAddress( address ) ) );
     }
 
-    @Test
-    void shouldBeAbleRunCypher() throws Exception
-    {
-        // Given
-        StubServer server = StubServer.start( "return_x.script", 9001 );
-        URI uri = URI.create( "bolt://127.0.0.1:9001" );
-        int x;
-
-        // When
-        try ( Driver driver = GraphDatabase.driver( uri, INSECURE_CONFIG ) )
-        {
-            try ( Session session = driver.session() )
-            {
-                Record record = session.run( "RETURN {x}", parameters( "x", 1 ) ).single();
-                x = record.get( 0 ).asInt();
-            }
-        }
-
-        // Then
-        assertThat( x, equalTo( 1 ) );
-
-        // Finally
-        assertThat( server.exitStatus(), equalTo( 0 ) );
-    }
-
-    @Test
-    void shouldSendMultipleBookmarks() throws Exception
-    {
-        StubServer server = StubServer.start( "multiple_bookmarks.script", 9001 );
-
-        List<String> bookmarks = Arrays.asList( "neo4j:bookmark:v1:tx5", "neo4j:bookmark:v1:tx29",
-                "neo4j:bookmark:v1:tx94", "neo4j:bookmark:v1:tx56", "neo4j:bookmark:v1:tx16",
-                "neo4j:bookmark:v1:tx68" );
-
-        try ( Driver driver = GraphDatabase.driver( "bolt://localhost:9001", INSECURE_CONFIG );
-              Session session = driver.session( bookmarks ) )
-        {
-            try ( Transaction tx = session.beginTransaction() )
-            {
-                tx.run( "CREATE (n {name:'Bob'})" );
-                tx.success();
-            }
-
-            assertEquals( "neo4j:bookmark:v1:tx95", session.lastBookmark() );
-        }
-        finally
-        {
-            assertEquals( 0, server.exitStatus() );
-        }
-    }
-
     @Test
     void shouldConnectIPv6Uri()
     {