Skip to content

Commit b428d48

Browse files
lutovichlutovich
authored
Merge pull request #531 from lutovich/1.7-connection-id
Include database connection ID in debug logs
2 parents 1014323 + d67a5b3 commit b428d48

File tree

12 files changed

+369
-78
lines changed

12 files changed

+369
-78
lines changed

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

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929

3030
public final class ChannelAttributes
3131
{
32+
private static final AttributeKey<String> CONNECTION_ID = newInstance( "connectionId" );
3233
private static final AttributeKey<Integer> PROTOCOL_VERSION = newInstance( "protocolVersion" );
3334
private static final AttributeKey<BoltServerAddress> ADDRESS = newInstance( "serverAddress" );
3435
private static final AttributeKey<ServerVersion> SERVER_VERSION = newInstance( "serverVersion" );
@@ -41,6 +42,16 @@ private ChannelAttributes()
4142
{
4243
}
4344

45+
public static String connectionId( Channel channel )
46+
{
47+
return get( channel, CONNECTION_ID );
48+
}
49+
50+
public static void setConnectionId( Channel channel, String id )
51+
{
52+
setOnce( channel, CONNECTION_ID, id );
53+
}
54+
4455
public static int protocolVersion( Channel channel )
4556
{
4657
return get( channel, PROTOCOL_VERSION );

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

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ public NettyChannelTracker( MetricsListener metricsListener, ChannelGroup channe
6262
@Override
6363
public void channelReleased( Channel channel )
6464
{
65-
log.debug( "Channel %s released back to the pool", channel );
65+
log.debug( "Channel [%s] released back to the pool", channel.id() );
6666
decrementInUse( channel );
6767
incrementIdle( channel );
6868
channel.closeFuture().addListener( closeListener );
@@ -71,7 +71,9 @@ public void channelReleased( Channel channel )
7171
@Override
7272
public void channelAcquired( Channel channel )
7373
{
74-
log.debug( "Channel %s acquired from the pool", channel );
74+
log.debug( "Channel [%s] acquired from the pool. Local address: %s, remote address: %s",
75+
channel.id(), channel.localAddress(), channel.remoteAddress() );
76+
7577
incrementInUse( channel );
7678
decrementIdle( channel );
7779
channel.closeFuture().removeListener( closeListener );
@@ -85,7 +87,9 @@ public void channelCreated( Channel channel )
8587

8688
public void channelCreated( Channel channel, ListenerEvent creatingEvent )
8789
{
88-
log.debug( "Channel %s created", channel );
90+
log.debug( "Channel [%s] created. Local address: %s, remote address: %s",
91+
channel.id(), channel.localAddress(), channel.remoteAddress() );
92+
8993
incrementInUse( channel );
9094
metricsListener.afterCreated( serverAddress( channel ), creatingEvent );
9195

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

Lines changed: 14 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -27,10 +27,14 @@
2727
import org.neo4j.driver.internal.util.ServerVersion;
2828
import org.neo4j.driver.v1.Value;
2929

30+
import static org.neo4j.driver.internal.async.ChannelAttributes.setConnectionId;
3031
import static org.neo4j.driver.internal.async.ChannelAttributes.setServerVersion;
3132

3233
public class HelloResponseHandler implements ResponseHandler
3334
{
35+
private static final String SERVER_METADATA_KEY = "server";
36+
private static final String CONNECTION_ID_METADATA_KEY = "connection_id";
37+
3438
private final ChannelPromise connectionInitializedPromise;
3539
private final Channel channel;
3640

@@ -45,8 +49,12 @@ public void onSuccess( Map<String,Value> metadata )
4549
{
4650
try
4751
{
48-
ServerVersion serverVersion = extractServerVersion( metadata );
52+
ServerVersion serverVersion = ServerVersion.version( extractMetadataValue( SERVER_METADATA_KEY, metadata ) );
4953
setServerVersion( channel, serverVersion );
54+
55+
String connectionId = extractMetadataValue( CONNECTION_ID_METADATA_KEY, metadata );
56+
setConnectionId( channel, connectionId );
57+
5058
connectionInitializedPromise.setSuccess();
5159
}
5260
catch ( Throwable error )
@@ -68,13 +76,13 @@ public void onRecord( Value[] fields )
6876
throw new UnsupportedOperationException();
6977
}
7078

71-
private static ServerVersion extractServerVersion( Map<String,Value> metadata )
79+
private static String extractMetadataValue( String key, Map<String,Value> metadata )
7280
{
73-
Value versionValue = metadata.get( "server" );
74-
if ( versionValue == null || versionValue.isNull() )
81+
Value value = metadata.get( key );
82+
if ( value == null || value.isNull() )
7583
{
76-
throw new IllegalStateException( "Unable to get server version from a response to HELLO message. Metadata: " + metadata );
84+
throw new IllegalStateException( "Unable to extract " + key + " from a response to HELLO message. Metadata: " + metadata );
7785
}
78-
return ServerVersion.version( versionValue.asString() );
86+
return value.asString();
7987
}
8088
}

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

Lines changed: 22 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020

2121
import io.netty.channel.Channel;
2222

23+
import org.neo4j.driver.internal.async.ChannelAttributes;
2324
import org.neo4j.driver.v1.Logger;
2425
import org.neo4j.driver.v1.Logging;
2526

@@ -28,6 +29,9 @@
2829
public class ChannelActivityLogger extends ReformattedLogger
2930
{
3031
private final Channel channel;
32+
private final String localChannelId;
33+
34+
private String dbConnectionId;
3135

3236
public ChannelActivityLogger( Channel channel, Logging logging, Class<?> owner )
3337
{
@@ -38,6 +42,7 @@ private ChannelActivityLogger( Channel channel, Logger delegate )
3842
{
3943
super( delegate );
4044
this.channel = channel;
45+
this.localChannelId = channel != null ? channel.id().toString() : null;
4146
}
4247

4348
@Override
@@ -47,6 +52,22 @@ protected String reformat( String message )
4752
{
4853
return message;
4954
}
50-
return format( "[0x%s] %s", channel.id(), message );
55+
56+
String dbConnectionId = getDbConnectionId();
57+
58+
if ( localChannelId != null && dbConnectionId != null )
59+
{
60+
return format( "[0x%s][%s] %s", localChannelId, dbConnectionId, message );
61+
}
62+
return format( "[0x%s][] %s", localChannelId, message );
63+
}
64+
65+
private String getDbConnectionId()
66+
{
67+
if ( dbConnectionId == null )
68+
{
69+
dbConnectionId = ChannelAttributes.connectionId( channel );
70+
}
71+
return dbConnectionId;
5172
}
5273
}

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

Lines changed: 132 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,132 @@
1+
/*
2+
* Copyright (c) 2002-2018 "Neo4j,"
3+
* Neo4j Sweden AB [http://neo4j.com]
4+
*
5+
* This file is part of Neo4j.
6+
*
7+
* Licensed under the Apache License, Version 2.0 (the "License");
8+
* you may not use this file except in compliance with the License.
9+
* You may obtain a copy of the License at
10+
*
11+
* http://www.apache.org/licenses/LICENSE-2.0
12+
*
13+
* Unless required by applicable law or agreed to in writing, software
14+
* distributed under the License is distributed on an "AS IS" BASIS,
15+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
16+
* See the License for the specific language governing permissions and
17+
* limitations under the License.
18+
*/
19+
package org.neo4j.driver.internal;
20+
21+
import org.junit.jupiter.api.Test;
22+
import org.mockito.ArgumentCaptor;
23+
24+
import java.net.URI;
25+
import java.util.List;
26+
import java.util.Optional;
27+
28+
import org.neo4j.driver.v1.Config;
29+
import org.neo4j.driver.v1.Driver;
30+
import org.neo4j.driver.v1.GraphDatabase;
31+
import org.neo4j.driver.v1.Logger;
32+
import org.neo4j.driver.v1.Record;
33+
import org.neo4j.driver.v1.Session;
34+
import org.neo4j.driver.v1.Transaction;
35+
import org.neo4j.driver.v1.util.StubServer;
36+
37+
import static java.util.Arrays.asList;
38+
import static org.hamcrest.core.IsEqual.equalTo;
39+
import static org.hamcrest.junit.MatcherAssert.assertThat;
40+
import static org.junit.jupiter.api.Assertions.assertEquals;
41+
import static org.junit.jupiter.api.Assertions.assertTrue;
42+
import static org.mockito.ArgumentMatchers.any;
43+
import static org.mockito.Mockito.atLeastOnce;
44+
import static org.mockito.Mockito.mock;
45+
import static org.mockito.Mockito.verify;
46+
import static org.mockito.Mockito.when;
47+
import static org.neo4j.driver.v1.Values.parameters;
48+
import static org.neo4j.driver.v1.util.StubServer.INSECURE_CONFIG;
49+
50+
class DirectDriverBoltKitTest
51+
{
52+
@Test
53+
void shouldBeAbleRunCypher() throws Exception
54+
{
55+
StubServer server = StubServer.start( "return_x.script", 9001 );
56+
URI uri = URI.create( "bolt://127.0.0.1:9001" );
57+
int x;
58+
59+
try ( Driver driver = GraphDatabase.driver( uri, INSECURE_CONFIG ) )
60+
{
61+
try ( Session session = driver.session() )
62+
{
63+
Record record = session.run( "RETURN {x}", parameters( "x", 1 ) ).single();
64+
x = record.get( 0 ).asInt();
65+
}
66+
}
67+
68+
assertThat( x, equalTo( 1 ) );
69+
assertThat( server.exitStatus(), equalTo( 0 ) );
70+
}
71+
72+
@Test
73+
void shouldSendMultipleBookmarks() throws Exception
74+
{
75+
StubServer server = StubServer.start( "multiple_bookmarks.script", 9001 );
76+
77+
List<String> bookmarks = asList( "neo4j:bookmark:v1:tx5", "neo4j:bookmark:v1:tx29",
78+
"neo4j:bookmark:v1:tx94", "neo4j:bookmark:v1:tx56", "neo4j:bookmark:v1:tx16",
79+
"neo4j:bookmark:v1:tx68" );
80+
81+
try ( Driver driver = GraphDatabase.driver( "bolt://localhost:9001", INSECURE_CONFIG );
82+
Session session = driver.session( bookmarks ) )
83+
{
84+
try ( Transaction tx = session.beginTransaction() )
85+
{
86+
tx.run( "CREATE (n {name:'Bob'})" );
87+
tx.success();
88+
}
89+
90+
assertEquals( "neo4j:bookmark:v1:tx95", session.lastBookmark() );
91+
}
92+
finally
93+
{
94+
assertEquals( 0, server.exitStatus() );
95+
}
96+
}
97+
98+
@Test
99+
void shouldLogConnectionIdInDebugMode() throws Exception
100+
{
101+
StubServer server = StubServer.start( "hello_run_exit.script", 9001 );
102+
103+
Logger logger = mock( Logger.class );
104+
when( logger.isDebugEnabled() ).thenReturn( true );
105+
106+
Config config = Config.build()
107+
.withLogging( ignore -> logger )
108+
.withoutEncryption().toConfig();
109+
110+
try ( Driver driver = GraphDatabase.driver( "bolt://localhost:9001", config );
111+
Session session = driver.session() )
112+
{
113+
List<String> names = session.run( "MATCH (n) RETURN n.name" ).list( record -> record.get( 0 ).asString() );
114+
assertEquals( asList( "Foo", "Bar" ), names );
115+
116+
ArgumentCaptor<String> messageCaptor = ArgumentCaptor.forClass( String.class );
117+
verify( logger, atLeastOnce() ).debug( messageCaptor.capture(), any() );
118+
119+
Optional<String> logMessageWithConnectionId = messageCaptor.getAllValues()
120+
.stream()
121+
.filter( line -> line.contains( "bolt-123456789" ) )
122+
.findAny();
123+
124+
assertTrue( logMessageWithConnectionId.isPresent(),
125+
"Expected log call did not happen. All debug log calls:\n" + String.join( "\n", messageCaptor.getAllValues() ) );
126+
}
127+
finally
128+
{
129+
assertEquals( 0, server.exitStatus() );
130+
}
131+
}
132+
}

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

Lines changed: 0 additions & 59 deletions
Original file line numberDiff line numberDiff line change
@@ -24,30 +24,22 @@
2424
import org.junit.jupiter.api.extension.RegisterExtension;
2525

2626
import java.net.URI;
27-
import java.util.Arrays;
28-
import java.util.List;
2927

3028
import org.neo4j.driver.internal.util.EnabledOnNeo4jWith;
3129
import org.neo4j.driver.v1.Driver;
3230
import org.neo4j.driver.v1.GraphDatabase;
33-
import org.neo4j.driver.v1.Record;
3431
import org.neo4j.driver.v1.Session;
3532
import org.neo4j.driver.v1.StatementResult;
36-
import org.neo4j.driver.v1.Transaction;
3733
import org.neo4j.driver.v1.util.DatabaseExtension;
38-
import org.neo4j.driver.v1.util.StubServer;
3934

4035
import static org.hamcrest.Matchers.is;
4136
import static org.hamcrest.core.IsEqual.equalTo;
4237
import static org.hamcrest.junit.MatcherAssert.assertThat;
43-
import static org.junit.jupiter.api.Assertions.assertEquals;
4438
import static org.junit.jupiter.api.Assertions.assertThrows;
4539
import static org.neo4j.driver.internal.BoltServerAddress.LOCAL_DEFAULT;
4640
import static org.neo4j.driver.internal.util.Matchers.directDriverWithAddress;
4741
import static org.neo4j.driver.internal.util.Neo4jFeature.CONNECTOR_LISTEN_ADDRESS_CONFIGURATION;
48-
import static org.neo4j.driver.v1.Values.parameters;
4942
import static org.neo4j.driver.v1.util.Neo4jRunner.DEFAULT_AUTH_TOKEN;
50-
import static org.neo4j.driver.v1.util.StubServer.INSECURE_CONFIG;
5143

5244
class DirectDriverIT
5345
{
@@ -118,57 +110,6 @@ void shouldRegisterSingleServer()
118110
assertThat( driver, is( directDriverWithAddress( address ) ) );
119111
}
120112

121-
@Test
122-
void shouldBeAbleRunCypher() throws Exception
123-
{
124-
// Given
125-
StubServer server = StubServer.start( "return_x.script", 9001 );
126-
URI uri = URI.create( "bolt://127.0.0.1:9001" );
127-
int x;
128-
129-
// When
130-
try ( Driver driver = GraphDatabase.driver( uri, INSECURE_CONFIG ) )
131-
{
132-
try ( Session session = driver.session() )
133-
{
134-
Record record = session.run( "RETURN {x}", parameters( "x", 1 ) ).single();
135-
x = record.get( 0 ).asInt();
136-
}
137-
}
138-
139-
// Then
140-
assertThat( x, equalTo( 1 ) );
141-
142-
// Finally
143-
assertThat( server.exitStatus(), equalTo( 0 ) );
144-
}
145-
146-
@Test
147-
void shouldSendMultipleBookmarks() throws Exception
148-
{
149-
StubServer server = StubServer.start( "multiple_bookmarks.script", 9001 );
150-
151-
List<String> bookmarks = Arrays.asList( "neo4j:bookmark:v1:tx5", "neo4j:bookmark:v1:tx29",
152-
"neo4j:bookmark:v1:tx94", "neo4j:bookmark:v1:tx56", "neo4j:bookmark:v1:tx16",
153-
"neo4j:bookmark:v1:tx68" );
154-
155-
try ( Driver driver = GraphDatabase.driver( "bolt://localhost:9001", INSECURE_CONFIG );
156-
Session session = driver.session( bookmarks ) )
157-
{
158-
try ( Transaction tx = session.beginTransaction() )
159-
{
160-
tx.run( "CREATE (n {name:'Bob'})" );
161-
tx.success();
162-
}
163-
164-
assertEquals( "neo4j:bookmark:v1:tx95", session.lastBookmark() );
165-
}
166-
finally
167-
{
168-
assertEquals( 0, server.exitStatus() );
169-
}
170-
}
171-
172113
@Test
173114
void shouldConnectIPv6Uri()
174115
{

0 commit comments

Comments
 (0)