diff --git a/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLog.java b/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLog.java index 3b0e550d52474..c735b37ed9a32 100644 --- a/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLog.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLog.java @@ -54,66 +54,66 @@ public BoltMessageLog( FileSystemAbstraction fileSystem, File logFile, Executor public void error( String remoteAddress, String message ) { - inner.error( "[%s] %s", remoteAddress, message ); + inner.error( "%s %s", remoteAddress, message ); } public void error( String remoteAddress, String message, String arg1 ) { - inner.error( "[%s] %s %s", remoteAddress, message, arg1 ); + inner.error( "%s %s %s", remoteAddress, message, arg1 ); } public void error( String remoteAddress, String message, String arg1, String arg2 ) { - inner.error( "[%s] %s %s %s", remoteAddress, message, arg1, arg2 ); + inner.error( "%s %s %s %s", remoteAddress, message, arg1, arg2 ); } public void warn( String remoteAddress, String message ) { - inner.warn( "[%s] %s", remoteAddress, message ); + inner.warn( "%s %s", remoteAddress, message ); } public void warn( String remoteAddress, String message, String arg1 ) { - inner.warn( "[%s] %s %s", remoteAddress, message, arg1 ); + inner.warn( "%s %s %s", remoteAddress, message, arg1 ); } public void warn( String remoteAddress, String message, String arg1, String arg2 ) { - inner.warn( "[%s] %s %s %s", remoteAddress, message, arg1, arg2 ); + inner.warn( "%s %s %s %s", remoteAddress, message, arg1, arg2 ); } public void info( String remoteAddress, String message ) { - inner.info( "[%s] %s", remoteAddress, message ); + inner.info( "%s %s", remoteAddress, message ); } public void info( String remoteAddress, String message, String arg1 ) { - inner.info( "[%s] %s %s", remoteAddress, message, arg1 ); + inner.info( "%s %s %s", remoteAddress, message, arg1 ); } public void info( String remoteAddress, String message, String arg1, String arg2 ) { - inner.info( "[%s] %s %s %s", remoteAddress, message, arg1, arg2 ); + inner.info( "%s %s %s %s", remoteAddress, message, arg1, arg2 ); } public void info( String remoteAddress, String message, String arg1, String arg2, String arg3 ) { - inner.info( "[%s] %s %s %s", remoteAddress, message, arg1, arg2, arg3 ); + inner.info( "%s %s %s %s", remoteAddress, message, arg1, arg2, arg3 ); } public void debug( String remoteAddress, String message ) { - inner.debug( "[%s] %s", remoteAddress, message ); + inner.debug( "%s %s", remoteAddress, message ); } public void debug( String remoteAddress, String message, String arg1 ) { - inner.debug( "[%s] %s %s", remoteAddress, message, arg1 ); + inner.debug( "%s %s %s", remoteAddress, message, arg1 ); } public void debug( String remoteAddress, String message, String arg1, String arg2 ) { - inner.debug( "[%s] %s %s %s", remoteAddress, message, arg1, arg2 ); + inner.debug( "%s %s %s %s", remoteAddress, message, arg1, arg2 ); } } diff --git a/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLoggerImpl.java b/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLoggerImpl.java index c97c9f275a550..3ccd3d006ed52 100644 --- a/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLoggerImpl.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/logging/BoltMessageLoggerImpl.java @@ -41,6 +41,7 @@ class BoltMessageLoggerImpl implements BoltMessageLogger { private static final ObjectMapper jsonObjectMapper = new ObjectMapper(); + public static final Supplier PLACEHOLDER_DETAIL_SUPPLIER = () -> "-"; private final BoltMessageLog messageLog; private final String remoteAddress; @@ -60,13 +61,13 @@ class BoltMessageLoggerImpl implements BoltMessageLogger @Override public void clientEvent( String eventName ) { - infoLogger().accept( format( "C: <%s>", eventName ) ); + clientEvent( eventName, PLACEHOLDER_DETAIL_SUPPLIER ); } @Override public void clientEvent( String eventName, Supplier detailsSupplier ) { - infoLoggerWithArgs().accept( format( "C: <%s>", eventName ), detailsSupplier.get() ); + infoLoggerWithDetails().accept( format( "C: %s", eventName ), detailsSupplier.get() ); } @Override @@ -78,13 +79,13 @@ public void clientError( String eventName, String errorMessage, Supplier @Override public void serverEvent( String eventName ) { - infoLogger().accept( format( "S: <%s>", eventName ) ); + serverEvent( eventName, PLACEHOLDER_DETAIL_SUPPLIER ); } @Override public void serverEvent( String eventName, Supplier detailsSupplier ) { - infoLoggerWithArgs().accept( format( "S: <%s>", eventName ), detailsSupplier.get() ); + infoLoggerWithDetails().accept( format( "S: %s", eventName ), detailsSupplier.get() ); } @Override @@ -103,67 +104,67 @@ public void serverError( String eventName, Status status, String errorMessage ) public void logInit( String userAgent, Map authToken ) { // log only auth toke keys, not values that include password - infoLoggerWithArgs().accept( "C: INIT", format( "%s %s", userAgent, json( authToken.keySet() ) ) ); + clientEvent( "INIT", () -> format( "%s %s", userAgent, json( authToken.keySet() ) ) ); } @Override public void logRun( String statement, Map parameters ) { - infoLoggerWithArgs().accept( "C: RUN", format( "%s %s", statement, json( parameters ) ) ); + clientEvent( "RUN", () -> format( "%s %s", statement, json( parameters ) ) ); } @Override public void logPullAll() { - infoLogger().accept( "C: PULL_ALL" ); + clientEvent( "PULL_ALL", PLACEHOLDER_DETAIL_SUPPLIER ); } @Override public void logDiscardAll() { - infoLogger().accept( "C: DISCARD_ALL" ); + clientEvent( "DISCARD_ALL", PLACEHOLDER_DETAIL_SUPPLIER ); } @Override public void logAckFailure() { - infoLogger().accept( "C: ACK_FAILURE" ); + clientEvent( "ACK_FAILURE", PLACEHOLDER_DETAIL_SUPPLIER ); } @Override public void logReset() { - infoLogger().accept( "C: RESET" ); + clientEvent( "RESET", PLACEHOLDER_DETAIL_SUPPLIER ); } @Override public void logSuccess( Object metadata ) { - infoLoggerWithArgs().accept( "S: SUCCESS", json( metadata ) ); + serverEvent( "SUCCESS", () -> json( metadata ) ); } @Override public void logFailure( Status status, String errorMessage ) { - infoLoggerWithArgs().accept( "S: FAILURE", format( "%s %s", status.code().serialize(), errorMessage ) ); + serverEvent( "FAILURE", () -> format( "%s %s", status.code().serialize(), errorMessage ) ); } @Override public void logIgnored() { - infoLogger().accept( "S: IGNORED" ); + serverEvent( "IGNORED", PLACEHOLDER_DETAIL_SUPPLIER ); } - private Consumer infoLogger() + private Consumer errorLogger( String errorMessage ) { if ( !channel.hasAttr( CORRELATION_ATTRIBUTE_KEY ) ) { channel.attr( CORRELATION_ATTRIBUTE_KEY ).set( randomCorrelationIdGenerator() ); } - String boltXCorrelationId = channel.attr( CORRELATION_ATTRIBUTE_KEY ).get(); + String boltCorrelationId = channel.attr( CORRELATION_ATTRIBUTE_KEY ).get(); return formatMessageWithEventName -> - messageLog.info( remoteAddress, formatMessageWithEventName, boltXCorrelationId ); + messageLog.error( remoteAddress, errorMessage, formatMessageWithEventName, boltCorrelationId ); } private String randomCorrelationIdGenerator() @@ -171,22 +172,18 @@ private String randomCorrelationIdGenerator() return UUID.randomUUID().toString(); } - private BiConsumer infoLoggerWithArgs() - { - return ( formatMessageWithEventName, details ) -> - infoLogger().accept( format( "%s %s", formatMessageWithEventName, details ) ); - } - - private Consumer errorLogger( String errorMessage ) + private BiConsumer infoLoggerWithDetails() { if ( !channel.hasAttr( CORRELATION_ATTRIBUTE_KEY ) ) { channel.attr( CORRELATION_ATTRIBUTE_KEY ).set( randomCorrelationIdGenerator() ); } - String boltXCorrelationId = channel.attr( CORRELATION_ATTRIBUTE_KEY ).get(); - return formatMessageWithEventName -> - messageLog.error( remoteAddress, errorMessage, formatMessageWithEventName, boltXCorrelationId ); + String boltCorrelationId = channel.attr( CORRELATION_ATTRIBUTE_KEY ).get(); + return ( formatMessageWithEventName, details ) -> + messageLog.info( remoteAddress, + boltCorrelationId, + format( "%s %s", formatMessageWithEventName, details ) ); } private BiConsumer errorLoggerWithArgs( String errorMessage ) diff --git a/community/bolt/src/test/java/org/neo4j/bolt/logging/BoltMessageLoggerImplTest.java b/community/bolt/src/test/java/org/neo4j/bolt/logging/BoltMessageLoggerImplTest.java index 9eb6ad3b3262d..cb9d9e2758c0b 100644 --- a/community/bolt/src/test/java/org/neo4j/bolt/logging/BoltMessageLoggerImplTest.java +++ b/community/bolt/src/test/java/org/neo4j/bolt/logging/BoltMessageLoggerImplTest.java @@ -1,6 +1,7 @@ package org.neo4j.bolt.logging; import java.net.InetSocketAddress; +import java.util.Collections; import io.netty.channel.Channel; import io.netty.util.Attribute; @@ -10,6 +11,9 @@ import org.mockito.Mock; import org.mockito.runners.MockitoJUnitRunner; +import org.neo4j.bolt.v1.runtime.Neo4jError; +import org.neo4j.kernel.DeadlockDetectedException; + import static org.mockito.Matchers.anyString; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; @@ -20,6 +24,8 @@ public class BoltMessageLoggerImplTest { + private static final String REMOTE_ADDRESS = "localhost/127.0.0.1:60297"; + private static final String CORRELATION_ID = "Bolt-X-CorrelationId-1234"; @Mock private Channel channel; @Mock @@ -27,50 +33,161 @@ public class BoltMessageLoggerImplTest @Mock Attribute correlationIdAttribute; - BoltMessageLoggerImpl boltMessageLogger; - @Before public void setUp() throws Exception { when( channel.remoteAddress() ).thenReturn( new InetSocketAddress( "localhost", 60297 ) ); - when( correlationIdAttribute.get() ).thenReturn( "Bolt-X-CorrelationId-1234" ); + when( correlationIdAttribute.get() ).thenReturn( CORRELATION_ID ); when( channel.attr( CORRELATION_ATTRIBUTE_KEY ) ).thenReturn( correlationIdAttribute ); boltMessageLogger = new BoltMessageLoggerImpl( boltMessageLog, channel ); } + @Test + public void clientEventWithDetails() throws Exception + { + // when + boltMessageLogger.clientEvent( "TEST", () -> "details" ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: TEST details" ); + } + + @Test + public void serverEvent() throws Exception + { + // when + boltMessageLogger.serverEvent( "TEST" ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "S: TEST -" ); + } + + @Test + public void serverEventWithDetails() throws Exception + { + // when + boltMessageLogger.serverEvent( "TEST", () -> "details" ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "S: TEST details" ); + } + + + @Test + public void logAckFailure() throws Exception + { + // when + boltMessageLogger.logAckFailure(); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: ACK_FAILURE -" ); + + } + + @Test + public void logInit() throws Exception + { + // when + boltMessageLogger.logInit( "userAgent", Collections.singletonMap( "username", "password" ) ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: INIT userAgent [\"username\"]" ); + + } + + @Test + public void logRun() throws Exception + { + // when + boltMessageLogger.logRun( "RETURN 42", Collections.singletonMap( "param1", "value" ) ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: RUN RETURN 42 {\"param1\":\"value\"}" ); + } + + @Test + public void logPullAll() throws Exception + { + // when + boltMessageLogger.logPullAll(); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: PULL_ALL -" ); + } + + @Test + public void logDiscardAll() throws Exception + { + // when + boltMessageLogger.logDiscardAll(); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: DISCARD_ALL -" ); + } + + @Test + public void logReset() throws Exception + { + // when + boltMessageLogger.logReset(); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: RESET -" ); + } + + @Test + public void logSuccess() throws Exception + { + // when + boltMessageLogger.logSuccess( "metadata" ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "S: SUCCESS \"metadata\"" ); + } + + @Test + public void logIgnored() throws Exception + { + // when + boltMessageLogger.logIgnored(); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "S: IGNORED -" ); + } + + @Test + public void logFailure() throws Exception + { + // given + String errorMessage = "Oh my woes!"; + Neo4jError error = Neo4jError.from( new DeadlockDetectedException( errorMessage ) ); + // when + boltMessageLogger.logFailure( error.status(), errorMessage ); + // then + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, + "S: FAILURE Neo.TransientError.Transaction.DeadlockDetected Oh my woes!" ); + + } + @Test public void logCorrelationIdClientEvent() throws Exception { // given - when( correlationIdAttribute.get() ).thenReturn( "Bolt-X-CorrelationId-1234" ); when( channel.hasAttr( CORRELATION_ATTRIBUTE_KEY ) ).thenReturn( true ); // when boltMessageLogger.clientEvent( "TEST" ); // then - verify( boltMessageLog ).info( "localhost/127.0.0.1:60297", "C: ", - "Bolt-X-CorrelationId-1234" ); + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: TEST -" ); } @Test public void logCorrelationIdClientErrorWithDetails() throws Exception { // given - when( correlationIdAttribute.get() ).thenReturn( "Bolt-X-CorrelationId-1234" ); + when( correlationIdAttribute.get() ).thenReturn( CORRELATION_ID ); when( channel.hasAttr( CORRELATION_ATTRIBUTE_KEY ) ).thenReturn( true ); // when boltMessageLogger.clientError( "TEST", "errorMessage", () -> "details" ); // then - verify( boltMessageLog ).error( "localhost/127.0.0.1:60297", "errorMessage", "C: details", - "Bolt-X-CorrelationId-1234" ); + verify( boltMessageLog ).error( REMOTE_ADDRESS, "errorMessage", "C: details", + CORRELATION_ID ); } - @Test public void logCorrelationIdServerError() throws Exception { @@ -81,15 +198,15 @@ public void logCorrelationIdServerError() throws Exception boltMessageLogger.serverError( "TEST", "errorMessage" ); // then - verify( boltMessageLog ).error( "localhost/127.0.0.1:60297", "errorMessage", "S: ", - "Bolt-X-CorrelationId-1234" ); + verify( boltMessageLog ).error( REMOTE_ADDRESS, "errorMessage", "S: ", + CORRELATION_ID ); } @Test public void logCorrelationIdClientEventWithDetails() throws Exception { // given - when( correlationIdAttribute.get() ).thenReturn( "Bolt-X-CorrelationId-1234" ); + when( correlationIdAttribute.get() ).thenReturn( CORRELATION_ID ); when( channel.hasAttr( CORRELATION_ATTRIBUTE_KEY ) ).thenReturn( true ); when( channel.attr( CORRELATION_ATTRIBUTE_KEY ) ).thenReturn( correlationIdAttribute ); @@ -97,8 +214,7 @@ public void logCorrelationIdClientEventWithDetails() throws Exception boltMessageLogger.clientEvent( "TEST", () -> "details" ); // then - verify( boltMessageLog ).info( "localhost/127.0.0.1:60297", "C: details", - "Bolt-X-CorrelationId-1234" ); + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: TEST details" ); } @Test @@ -113,7 +229,7 @@ public void createCorrelationIdIfNotAvailableInInfoLogger() throws Exception // then verify( correlationIdAttribute ).set( anyString() ); - verify( boltMessageLog ).info( "localhost/127.0.0.1:60297", "C: ", "Bolt-X-CorrelationId-1234" ); + verify( boltMessageLog ).info( REMOTE_ADDRESS, CORRELATION_ID, "C: TEST -" ); } @Test @@ -128,7 +244,7 @@ public void createCorrelationIdIfNotAvailableInErrorLogger() throws Exception // then verify( correlationIdAttribute ).set( anyString() ); - verify( boltMessageLog ).error( "localhost/127.0.0.1:60297", "errorMessage", "S: ", - "Bolt-X-CorrelationId-1234" ); + verify( boltMessageLog ).error( REMOTE_ADDRESS, "errorMessage", "S: ", + CORRELATION_ID ); } }