Skip to content

Commit ba0cf3f

Browse files
committed
Fix possible logger leak
Various components like session and connection include their identifiers in logs for diagnostic purposes. Most did this by creating loggers with specialized names. This is a problematic approach because it forces logging framework to create many distinct logger objects. JUL keeps such loggers as weakly referenced values in a map. This caused excessive GC activity and application failures. This commit introduces a logger able to prepend diagnostics to messages and delegate rest of the work. It makes identifiers part of messages. Session, connection and other objects that require identification in logs now use this logger. Example log message: `2017-04-25 02:36:47,319 [ConnectionQueue] [127.0.0.1] Error disposing connection`
1 parent 503a3ee commit ba0cf3f

File tree

7 files changed

+400
-52
lines changed

7 files changed

+400
-52
lines changed

driver/src/main/java/org/neo4j/driver/internal/NetworkSession.java

Lines changed: 4 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -18,11 +18,10 @@
1818
*/
1919
package org.neo4j.driver.internal;
2020

21-
import java.util.ArrayList;
22-
import java.util.List;
2321
import java.util.Map;
2422
import java.util.concurrent.atomic.AtomicBoolean;
2523

24+
import org.neo4j.driver.internal.logging.DelegatingLogger;
2625
import org.neo4j.driver.internal.retry.RetryLogic;
2726
import org.neo4j.driver.internal.spi.Connection;
2827
import org.neo4j.driver.internal.spi.ConnectionProvider;
@@ -47,6 +46,8 @@
4746

4847
public class NetworkSession implements Session, SessionResourcesHandler
4948
{
49+
private static final String LOG_NAME = "Session";
50+
5051
private final ConnectionProvider connectionProvider;
5152
private final AccessMode mode;
5253
private final RetryLogic retryLogic;
@@ -64,7 +65,7 @@ public NetworkSession( ConnectionProvider connectionProvider, AccessMode mode, R
6465
this.connectionProvider = connectionProvider;
6566
this.mode = mode;
6667
this.retryLogic = retryLogic;
67-
this.logger = logging.getLog( "Session-" + hashCode() );
68+
this.logger = new DelegatingLogger( logging.getLog( LOG_NAME ), String.valueOf( hashCode() ) );
6869
}
6970

7071
@Override
@@ -378,28 +379,4 @@ private void closeCurrentConnection( boolean sync )
378379
logger.debug( "Released connection " + connection.hashCode() );
379380
}
380381
}
381-
382-
private static List<Throwable> recordError( Throwable error, List<Throwable> errors )
383-
{
384-
if ( errors == null )
385-
{
386-
errors = new ArrayList<>();
387-
}
388-
errors.add( error );
389-
return errors;
390-
}
391-
392-
private static void addSuppressed( Throwable error, List<Throwable> suppressedErrors )
393-
{
394-
if ( suppressedErrors != null )
395-
{
396-
for ( Throwable suppressedError : suppressedErrors )
397-
{
398-
if ( error != suppressedError )
399-
{
400-
error.addSuppressed( suppressedError );
401-
}
402-
}
403-
}
404-
}
405382
}
Lines changed: 97 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,97 @@
1+
/*
2+
* Copyright (c) 2002-2017 "Neo Technology,"
3+
* Network Engine for Objects in Lund AB [http://neotechnology.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.logging;
20+
21+
import org.neo4j.driver.v1.Logger;
22+
23+
import static java.util.Objects.requireNonNull;
24+
25+
public class DelegatingLogger implements Logger
26+
{
27+
private final Logger delegate;
28+
private final String messagePrefix;
29+
30+
public DelegatingLogger( Logger delegate )
31+
{
32+
this( delegate, null );
33+
}
34+
35+
public DelegatingLogger( Logger delegate, String messagePrefix )
36+
{
37+
this.delegate = requireNonNull( delegate );
38+
this.messagePrefix = messagePrefix;
39+
}
40+
41+
@Override
42+
public void error( String message, Throwable cause )
43+
{
44+
delegate.error( messageWithPrefix( message ), cause );
45+
}
46+
47+
@Override
48+
public void info( String message, Object... params )
49+
{
50+
delegate.info( messageWithPrefix( message ), params );
51+
}
52+
53+
@Override
54+
public void warn( String message, Object... params )
55+
{
56+
delegate.warn( messageWithPrefix( message ), params );
57+
}
58+
59+
@Override
60+
public void debug( String message, Object... params )
61+
{
62+
if ( isDebugEnabled() )
63+
{
64+
delegate.debug( messageWithPrefix( message ), params );
65+
}
66+
}
67+
68+
@Override
69+
public void trace( String message, Object... params )
70+
{
71+
if ( isTraceEnabled() )
72+
{
73+
delegate.trace( messageWithPrefix( message ), params );
74+
}
75+
}
76+
77+
@Override
78+
public boolean isTraceEnabled()
79+
{
80+
return delegate.isTraceEnabled();
81+
}
82+
83+
@Override
84+
public boolean isDebugEnabled()
85+
{
86+
return delegate.isDebugEnabled();
87+
}
88+
89+
private String messageWithPrefix( String message )
90+
{
91+
if ( messagePrefix == null )
92+
{
93+
return message;
94+
}
95+
return String.format( "[%s] %s", messagePrefix, message );
96+
}
97+
}

driver/src/main/java/org/neo4j/driver/internal/net/SocketConnection.java

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
import java.util.Queue;
2626
import java.util.concurrent.atomic.AtomicBoolean;
2727

28+
import org.neo4j.driver.internal.logging.DelegatingLogger;
2829
import org.neo4j.driver.internal.messaging.InitMessage;
2930
import org.neo4j.driver.internal.messaging.Message;
3031
import org.neo4j.driver.internal.messaging.RunMessage;
@@ -47,6 +48,8 @@
4748

4849
public class SocketConnection implements Connection
4950
{
51+
private static final String LOG_NAME = "Connection";
52+
5053
private final Queue<Message> pendingMessages = new LinkedList<>();
5154
private final SocketResponseHandler responseHandler;
5255
private final AtomicBoolean isInterrupted = new AtomicBoolean( false );
@@ -57,7 +60,7 @@ public class SocketConnection implements Connection
5760

5861
SocketConnection( BoltServerAddress address, SecurityPlan securityPlan, int timeoutMillis, Logging logging )
5962
{
60-
Logger logger = logging.getLog( "Connection-" + hashCode() );
63+
Logger logger = new DelegatingLogger( logging.getLog( LOG_NAME ), String.valueOf( hashCode() ) );
6164
this.socket = new SocketClient( address, securityPlan, timeoutMillis, logger );
6265
this.responseHandler = createResponseHandler( logger );
6366

driver/src/main/java/org/neo4j/driver/internal/net/pooling/BlockingPooledConnectionQueue.java

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@
2727
import java.util.concurrent.LinkedBlockingQueue;
2828
import java.util.concurrent.atomic.AtomicBoolean;
2929

30+
import org.neo4j.driver.internal.logging.DelegatingLogger;
3031
import org.neo4j.driver.internal.net.BoltServerAddress;
3132
import org.neo4j.driver.internal.spi.PooledConnection;
3233
import org.neo4j.driver.internal.util.Supplier;
@@ -39,6 +40,8 @@
3940
*/
4041
public class BlockingPooledConnectionQueue
4142
{
43+
public static final String LOG_NAME = "ConnectionQueue";
44+
4245
/** The backing queue, keeps track of connections currently in queue */
4346
private final BlockingQueue<PooledConnection> queue;
4447
private final Logger logger;
@@ -162,6 +165,6 @@ private void disposeSafely( PooledConnection connection )
162165

163166
private static Logger createLogger( BoltServerAddress address, Logging logging )
164167
{
165-
return logging.getLog( "ConnectionQueue[" + address + "]" );
168+
return new DelegatingLogger( logging.getLog( LOG_NAME ), address.toString() );
166169
}
167170
}

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

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,6 @@
3636
import org.neo4j.driver.v1.Session;
3737

3838
import static org.hamcrest.Matchers.containsString;
39-
import static org.hamcrest.Matchers.startsWith;
4039
import static org.junit.Assert.assertEquals;
4140
import static org.junit.Assert.assertThat;
4241
import static org.mockito.Matchers.any;
@@ -83,7 +82,7 @@ public void logsMessageWithStacktraceDuringFinalizationIfLeaked() throws Excepti
8382
assertEquals( 1, messageCaptor.getAllValues().size() );
8483

8584
String loggedMessage = messageCaptor.getValue();
86-
assertThat( loggedMessage, startsWith( "Neo4j Session object leaked" ) );
85+
assertThat( loggedMessage, containsString( "Neo4j Session object leaked" ) );
8786
assertThat( loggedMessage, containsString( "Session was create at" ) );
8887
assertThat( loggedMessage, containsString(
8988
getClass().getSimpleName() + "." + testName.getMethodName() )

0 commit comments

Comments
 (0)