diff --git a/driver/src/main/java/org/neo4j/driver/internal/NetworkSession.java b/driver/src/main/java/org/neo4j/driver/internal/NetworkSession.java index 700c9df2d4..43607c1b49 100644 --- a/driver/src/main/java/org/neo4j/driver/internal/NetworkSession.java +++ b/driver/src/main/java/org/neo4j/driver/internal/NetworkSession.java @@ -18,11 +18,10 @@ */ package org.neo4j.driver.internal; -import java.util.ArrayList; -import java.util.List; import java.util.Map; import java.util.concurrent.atomic.AtomicBoolean; +import org.neo4j.driver.internal.logging.DelegatingLogger; import org.neo4j.driver.internal.retry.RetryLogic; import org.neo4j.driver.internal.spi.Connection; import org.neo4j.driver.internal.spi.ConnectionProvider; @@ -47,6 +46,8 @@ public class NetworkSession implements Session, SessionResourcesHandler { + private static final String LOG_NAME = "Session"; + private final ConnectionProvider connectionProvider; private final AccessMode mode; private final RetryLogic retryLogic; @@ -64,7 +65,7 @@ public NetworkSession( ConnectionProvider connectionProvider, AccessMode mode, R this.connectionProvider = connectionProvider; this.mode = mode; this.retryLogic = retryLogic; - this.logger = logging.getLog( "Session-" + hashCode() ); + this.logger = new DelegatingLogger( logging.getLog( LOG_NAME ), String.valueOf( hashCode() ) ); } @Override @@ -378,28 +379,4 @@ private void closeCurrentConnection( boolean sync ) logger.debug( "Released connection " + connection.hashCode() ); } } - - private static List recordError( Throwable error, List errors ) - { - if ( errors == null ) - { - errors = new ArrayList<>(); - } - errors.add( error ); - return errors; - } - - private static void addSuppressed( Throwable error, List suppressedErrors ) - { - if ( suppressedErrors != null ) - { - for ( Throwable suppressedError : suppressedErrors ) - { - if ( error != suppressedError ) - { - error.addSuppressed( suppressedError ); - } - } - } - } } diff --git a/driver/src/main/java/org/neo4j/driver/internal/logging/DelegatingLogger.java b/driver/src/main/java/org/neo4j/driver/internal/logging/DelegatingLogger.java new file mode 100644 index 0000000000..ab4e24e39a --- /dev/null +++ b/driver/src/main/java/org/neo4j/driver/internal/logging/DelegatingLogger.java @@ -0,0 +1,97 @@ +/* + * Copyright (c) 2002-2017 "Neo Technology," + * Network Engine for Objects in Lund AB [http://neotechnology.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.logging; + +import org.neo4j.driver.v1.Logger; + +import static java.util.Objects.requireNonNull; + +public class DelegatingLogger implements Logger +{ + private final Logger delegate; + private final String messagePrefix; + + public DelegatingLogger( Logger delegate ) + { + this( delegate, null ); + } + + public DelegatingLogger( Logger delegate, String messagePrefix ) + { + this.delegate = requireNonNull( delegate ); + this.messagePrefix = messagePrefix; + } + + @Override + public void error( String message, Throwable cause ) + { + delegate.error( messageWithPrefix( message ), cause ); + } + + @Override + public void info( String message, Object... params ) + { + delegate.info( messageWithPrefix( message ), params ); + } + + @Override + public void warn( String message, Object... params ) + { + delegate.warn( messageWithPrefix( message ), params ); + } + + @Override + public void debug( String message, Object... params ) + { + if ( isDebugEnabled() ) + { + delegate.debug( messageWithPrefix( message ), params ); + } + } + + @Override + public void trace( String message, Object... params ) + { + if ( isTraceEnabled() ) + { + delegate.trace( messageWithPrefix( message ), params ); + } + } + + @Override + public boolean isTraceEnabled() + { + return delegate.isTraceEnabled(); + } + + @Override + public boolean isDebugEnabled() + { + return delegate.isDebugEnabled(); + } + + private String messageWithPrefix( String message ) + { + if ( messagePrefix == null ) + { + return message; + } + return String.format( "[%s] %s", messagePrefix, message ); + } +} diff --git a/driver/src/main/java/org/neo4j/driver/internal/net/SocketConnection.java b/driver/src/main/java/org/neo4j/driver/internal/net/SocketConnection.java index 5bd390a4ad..4d25c48a20 100644 --- a/driver/src/main/java/org/neo4j/driver/internal/net/SocketConnection.java +++ b/driver/src/main/java/org/neo4j/driver/internal/net/SocketConnection.java @@ -25,6 +25,7 @@ import java.util.Queue; import java.util.concurrent.atomic.AtomicBoolean; +import org.neo4j.driver.internal.logging.DelegatingLogger; import org.neo4j.driver.internal.messaging.InitMessage; import org.neo4j.driver.internal.messaging.Message; import org.neo4j.driver.internal.messaging.RunMessage; @@ -47,6 +48,8 @@ public class SocketConnection implements Connection { + private static final String LOG_NAME = "Connection"; + private final Queue pendingMessages = new LinkedList<>(); private final SocketResponseHandler responseHandler; private final AtomicBoolean isInterrupted = new AtomicBoolean( false ); @@ -57,7 +60,7 @@ public class SocketConnection implements Connection SocketConnection( BoltServerAddress address, SecurityPlan securityPlan, int timeoutMillis, Logging logging ) { - Logger logger = logging.getLog( "Connection-" + hashCode() ); + Logger logger = new DelegatingLogger( logging.getLog( LOG_NAME ), String.valueOf( hashCode() ) ); this.socket = new SocketClient( address, securityPlan, timeoutMillis, logger ); this.responseHandler = createResponseHandler( logger ); diff --git a/driver/src/main/java/org/neo4j/driver/internal/net/pooling/BlockingPooledConnectionQueue.java b/driver/src/main/java/org/neo4j/driver/internal/net/pooling/BlockingPooledConnectionQueue.java index 9025347c9d..a62f757aa5 100644 --- a/driver/src/main/java/org/neo4j/driver/internal/net/pooling/BlockingPooledConnectionQueue.java +++ b/driver/src/main/java/org/neo4j/driver/internal/net/pooling/BlockingPooledConnectionQueue.java @@ -27,6 +27,7 @@ import java.util.concurrent.LinkedBlockingQueue; import java.util.concurrent.atomic.AtomicBoolean; +import org.neo4j.driver.internal.logging.DelegatingLogger; import org.neo4j.driver.internal.net.BoltServerAddress; import org.neo4j.driver.internal.spi.PooledConnection; import org.neo4j.driver.internal.util.Supplier; @@ -39,6 +40,8 @@ */ public class BlockingPooledConnectionQueue { + public static final String LOG_NAME = "ConnectionQueue"; + /** The backing queue, keeps track of connections currently in queue */ private final BlockingQueue queue; private final Logger logger; @@ -162,6 +165,6 @@ private void disposeSafely( PooledConnection connection ) private static Logger createLogger( BoltServerAddress address, Logging logging ) { - return logging.getLog( "ConnectionQueue[" + address + "]" ); + return new DelegatingLogger( logging.getLog( LOG_NAME ), address.toString() ); } } diff --git a/driver/src/test/java/org/neo4j/driver/internal/LeakLoggingNetworkSessionTest.java b/driver/src/test/java/org/neo4j/driver/internal/LeakLoggingNetworkSessionTest.java index a1a6b8f08e..1249acb047 100644 --- a/driver/src/test/java/org/neo4j/driver/internal/LeakLoggingNetworkSessionTest.java +++ b/driver/src/test/java/org/neo4j/driver/internal/LeakLoggingNetworkSessionTest.java @@ -36,7 +36,6 @@ import org.neo4j.driver.v1.Session; import static org.hamcrest.Matchers.containsString; -import static org.hamcrest.Matchers.startsWith; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertThat; import static org.mockito.Matchers.any; @@ -83,7 +82,7 @@ public void logsMessageWithStacktraceDuringFinalizationIfLeaked() throws Excepti assertEquals( 1, messageCaptor.getAllValues().size() ); String loggedMessage = messageCaptor.getValue(); - assertThat( loggedMessage, startsWith( "Neo4j Session object leaked" ) ); + assertThat( loggedMessage, containsString( "Neo4j Session object leaked" ) ); assertThat( loggedMessage, containsString( "Session was create at" ) ); assertThat( loggedMessage, containsString( getClass().getSimpleName() + "." + testName.getMethodName() ) diff --git a/driver/src/test/java/org/neo4j/driver/internal/logging/DelegatingLoggerTest.java b/driver/src/test/java/org/neo4j/driver/internal/logging/DelegatingLoggerTest.java new file mode 100644 index 0000000000..29dcc111bc --- /dev/null +++ b/driver/src/test/java/org/neo4j/driver/internal/logging/DelegatingLoggerTest.java @@ -0,0 +1,229 @@ +/* + * Copyright (c) 2002-2017 "Neo Technology," + * Network Engine for Objects in Lund AB [http://neotechnology.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.logging; + +import org.junit.Test; + +import org.neo4j.driver.v1.Logger; + +import static org.hamcrest.Matchers.instanceOf; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertThat; +import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; +import static org.mockito.Matchers.anyString; +import static org.mockito.Matchers.anyVararg; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; + +public class DelegatingLoggerTest +{ + private static final String PREFIX = "Output"; + private static final String MESSAGE = "Hello World!"; + private static final Exception ERROR = new Exception(); + + @Test + public void shouldThrowWhenDelegateIsNull() + { + try + { + new DelegatingLogger( null ); + fail( "Exception expected" ); + } + catch ( Exception e ) + { + assertThat( e, instanceOf( NullPointerException.class ) ); + } + } + + @Test + public void shouldAllowNullPrefix() + { + assertNotNull( new DelegatingLogger( newLoggerMock(), null ) ); + } + + @Test + public void shouldDelegateIsDebugEnabled() + { + Logger delegate = newLoggerMock( true, false ); + + DelegatingLogger logger = new DelegatingLogger( delegate ); + + assertTrue( logger.isDebugEnabled() ); + verify( delegate ).isDebugEnabled(); + } + + @Test + public void shouldDelegateIsTraceEnabled() + { + Logger delegate = newLoggerMock( false, true ); + + DelegatingLogger logger = new DelegatingLogger( delegate ); + + assertTrue( logger.isTraceEnabled() ); + verify( delegate ).isTraceEnabled(); + } + + @Test + public void shouldNotDelegateDebugLogWhenDebugDisabled() + { + Logger delegate = newLoggerMock(); + + DelegatingLogger logger = new DelegatingLogger( delegate ); + logger.debug( MESSAGE ); + + verify( delegate, never() ).debug( anyString(), anyVararg() ); + } + + @Test + public void shouldNotDelegateTraceLogWhenTraceDisabled() + { + Logger delegate = newLoggerMock(); + + DelegatingLogger logger = new DelegatingLogger( delegate ); + logger.trace( MESSAGE ); + + verify( delegate, never() ).trace( anyString(), anyVararg() ); + } + + @Test + public void shouldDelegateErrorMessageWhenNoPrefix() + { + Logger delegate = newLoggerMock(); + DelegatingLogger logger = new DelegatingLogger( delegate ); + + logger.error( MESSAGE, ERROR ); + + verify( delegate ).error( MESSAGE, ERROR ); + } + + @Test + public void shouldDelegateInfoMessageWhenNoPrefix() + { + Logger delegate = newLoggerMock(); + DelegatingLogger logger = new DelegatingLogger( delegate ); + + logger.info( MESSAGE ); + + verify( delegate ).info( MESSAGE ); + } + + @Test + public void shouldDelegateWarnMessageWhenNoPrefix() + { + Logger delegate = newLoggerMock(); + DelegatingLogger logger = new DelegatingLogger( delegate ); + + logger.warn( MESSAGE ); + + verify( delegate ).warn( MESSAGE ); + } + + @Test + public void shouldDelegateDebugMessageWhenNoPrefix() + { + Logger delegate = newLoggerMock( true, false ); + DelegatingLogger logger = new DelegatingLogger( delegate ); + + logger.debug( MESSAGE ); + + verify( delegate ).debug( MESSAGE ); + } + + @Test + public void shouldDelegateTraceMessageWhenNoPrefix() + { + Logger delegate = newLoggerMock( false, true ); + DelegatingLogger logger = new DelegatingLogger( delegate ); + + logger.trace( MESSAGE ); + + verify( delegate ).trace( MESSAGE ); + } + + @Test + public void shouldDelegateErrorMessageWithPrefix() + { + Logger delegate = newLoggerMock(); + DelegatingLogger logger = new DelegatingLogger( delegate, PREFIX ); + + logger.error( MESSAGE, ERROR ); + + verify( delegate ).error( "[Output] Hello World!", ERROR ); + } + + @Test + public void shouldDelegateInfoMessageWithPrefix() + { + Logger delegate = newLoggerMock(); + DelegatingLogger logger = new DelegatingLogger( delegate, PREFIX ); + + logger.info( MESSAGE ); + + verify( delegate ).info( "[Output] Hello World!" ); + } + + @Test + public void shouldDelegateWarnMessageWithPrefix() + { + Logger delegate = newLoggerMock(); + DelegatingLogger logger = new DelegatingLogger( delegate, PREFIX ); + + logger.warn( MESSAGE ); + + verify( delegate ).warn( "[Output] Hello World!" ); + } + + @Test + public void shouldDelegateDebugMessageWithPrefix() + { + Logger delegate = newLoggerMock( true, false ); + DelegatingLogger logger = new DelegatingLogger( delegate, PREFIX ); + + logger.debug( MESSAGE ); + + verify( delegate ).debug( "[Output] Hello World!" ); + } + + @Test + public void shouldDelegateTraceMessageWithPrefix() + { + Logger delegate = newLoggerMock( false, true ); + DelegatingLogger logger = new DelegatingLogger( delegate, PREFIX ); + + logger.trace( MESSAGE ); + + verify( delegate ).trace( "[Output] Hello World!" ); + } + + private static Logger newLoggerMock() + { + return newLoggerMock( false, false ); + } + + private static Logger newLoggerMock( boolean debugEnabled, boolean traceEnabled ) + { + Logger logger = mock( Logger.class ); + when( logger.isDebugEnabled() ).thenReturn( debugEnabled ); + when( logger.isTraceEnabled() ).thenReturn( traceEnabled ); + return logger; + } +} diff --git a/driver/src/test/java/org/neo4j/driver/v1/stress/CausalClusteringStressIT.java b/driver/src/test/java/org/neo4j/driver/v1/stress/CausalClusteringStressIT.java index 001062900a..8b9b259907 100644 --- a/driver/src/test/java/org/neo4j/driver/v1/stress/CausalClusteringStressIT.java +++ b/driver/src/test/java/org/neo4j/driver/v1/stress/CausalClusteringStressIT.java @@ -22,15 +22,17 @@ import org.junit.Before; import org.junit.Rule; import org.junit.Test; -import org.mockito.ArgumentCaptor; import java.lang.management.ManagementFactory; import java.lang.management.OperatingSystemMXBean; import java.lang.reflect.Method; import java.net.URI; import java.util.ArrayList; +import java.util.HashSet; import java.util.List; +import java.util.Set; import java.util.concurrent.Callable; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.Future; @@ -39,6 +41,7 @@ import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; +import org.neo4j.driver.internal.logging.DevNullLogger; import org.neo4j.driver.v1.AccessMode; import org.neo4j.driver.v1.AuthToken; import org.neo4j.driver.v1.Config; @@ -56,7 +59,9 @@ import org.neo4j.driver.v1.util.DaemonThreadFactory; import org.neo4j.driver.v1.util.cc.LocalOrRemoteClusterRule; +import static java.util.Collections.newSetFromMap; import static org.hamcrest.Matchers.containsString; +import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.instanceOf; import static org.hamcrest.Matchers.lessThanOrEqualTo; import static org.junit.Assert.assertEquals; @@ -64,12 +69,6 @@ import static org.junit.Assert.assertNull; import static org.junit.Assert.assertThat; import static org.junit.Assert.fail; -import static org.mockito.Matchers.anyString; -import static org.mockito.Matchers.startsWith; -import static org.mockito.Mockito.mock; -import static org.mockito.Mockito.verify; -import static org.mockito.Mockito.when; -import static org.neo4j.driver.internal.logging.DevNullLogging.DEV_NULL_LOGGING; import static org.neo4j.driver.internal.util.Iterables.single; import static org.neo4j.driver.v1.AuthTokens.basic; @@ -81,15 +80,18 @@ public class CausalClusteringStressIT @Rule public final LocalOrRemoteClusterRule clusterRule = new LocalOrRemoteClusterRule(); + private TrackingDevNullLogging logging; private ExecutorService executor; private Driver driver; @Before public void setUp() throws Exception { + logging = new TrackingDevNullLogging(); + URI clusterUri = clusterRule.getClusterUri(); AuthToken authToken = clusterRule.getAuthToken(); - Config config = Config.build().withLogging( DEV_NULL_LOGGING ).withMaxIdleSessions( THREAD_COUNT ).toConfig(); + Config config = Config.build().withLogging( logging ).withMaxIdleSessions( THREAD_COUNT ).toConfig(); driver = GraphDatabase.driver( clusterUri, authToken, config ); ThreadFactory threadFactory = new DaemonThreadFactory( getClass().getSimpleName() + "-worker-" ); @@ -112,7 +114,7 @@ public void basicStressTest() throws Throwable Context context = new Context(); List> resultFutures = launchWorkerThreads( context ); - long openFileDescriptors = sleepAndGetOpenFileDescriptorCount(); + ResourcesInfo resourcesInfo = sleepAndGetResourcesInfo(); context.stop(); Throwable firstError = null; @@ -133,7 +135,8 @@ public void basicStressTest() throws Throwable throw firstError; } - assertNoFileDescriptorLeak( openFileDescriptors ); + assertNoFileDescriptorLeak( resourcesInfo.openFileDescriptorCount ); + assertNoLoggersLeak( resourcesInfo.acquiredLoggerNames ); assertExpectedNumberOfNodesCreated( context.getCreatedNodesCount() ); } @@ -167,7 +170,7 @@ private List createCommands() commands.add( new WriteQueryUsingReadSession( driver, true ) ); commands.add( new WriteQueryUsingReadSessionInTx( driver, false ) ); commands.add( new WriteQueryUsingReadSessionInTx( driver, true ) ); - commands.add( new FailedAuth( clusterRule.getClusterUri() ) ); + commands.add( new FailedAuth( clusterRule.getClusterUri(), logging ) ); return commands; } @@ -193,13 +196,15 @@ public Void call() throws Exception } ); } - private static long sleepAndGetOpenFileDescriptorCount() throws InterruptedException + private ResourcesInfo sleepAndGetResourcesInfo() throws InterruptedException { int halfSleepSeconds = Math.max( 1, EXECUTION_TIME_SECONDS / 2 ); TimeUnit.SECONDS.sleep( halfSleepSeconds ); long openFileDescriptorCount = getOpenFileDescriptorCount(); + Set acquiredLoggerNames = logging.getAcquiredLoggerNames(); + ResourcesInfo resourcesInfo = new ResourcesInfo( openFileDescriptorCount, acquiredLoggerNames ); TimeUnit.SECONDS.sleep( halfSleepSeconds ); - return openFileDescriptorCount; + return resourcesInfo; } private void assertNoFileDescriptorLeak( long previousOpenFileDescriptors ) @@ -211,6 +216,13 @@ private void assertNoFileDescriptorLeak( long previousOpenFileDescriptors ) currentOpenFileDescriptorCount, lessThanOrEqualTo( maxOpenFileDescriptors ) ); } + private void assertNoLoggersLeak( Set previousAcquiredLoggerNames ) + { + Set currentAcquiredLoggerNames = logging.getAcquiredLoggerNames(); + assertThat( "Unexpected amount of logger instances", + currentAcquiredLoggerNames, equalTo( previousAcquiredLoggerNames ) ); + } + private void assertExpectedNumberOfNodesCreated( long expectedCount ) { try ( Session session = driver.session() ) @@ -468,18 +480,17 @@ public void execute( Context context ) private static class FailedAuth implements Command { final URI clusterUri; + final Logging logging; - FailedAuth( URI clusterUri ) + FailedAuth( URI clusterUri, Logging logging ) { this.clusterUri = clusterUri; + this.logging = logging; } @Override public void execute( Context context ) { - Logger logger = mock( Logger.class ); - Logging logging = mock( Logging.class ); - when( logging.getLog( anyString() ) ).thenReturn( logger ); Config config = Config.build().withLogging( logging ).toConfig(); try @@ -491,11 +502,36 @@ public void execute( Context context ) { assertThat( e, instanceOf( SecurityException.class ) ); assertThat( e.getMessage(), containsString( "authentication failure" ) ); - - ArgumentCaptor captor = ArgumentCaptor.forClass( Throwable.class ); - verify( logger ).debug( startsWith( "~~ [CLOSED SECURE CHANNEL]" ), captor.capture() ); - verify( logger ).debug( startsWith( "~~ [DISCONNECT]" ), captor.capture() ); } } } + + private static class ResourcesInfo + { + final long openFileDescriptorCount; + final Set acquiredLoggerNames; + + ResourcesInfo( long openFileDescriptorCount, Set acquiredLoggerNames ) + { + this.openFileDescriptorCount = openFileDescriptorCount; + this.acquiredLoggerNames = acquiredLoggerNames; + } + } + + private static class TrackingDevNullLogging implements Logging + { + private final Set acquiredLoggerNames = newSetFromMap( new ConcurrentHashMap() ); + + @Override + public Logger getLog( String name ) + { + acquiredLoggerNames.add( name ); + return DevNullLogger.DEV_NULL_LOGGER; + } + + public Set getAcquiredLoggerNames() + { + return new HashSet<>( acquiredLoggerNames ); + } + } }