Skip to content

Commit

Permalink
Cleanup error logging in Bolt
Browse files Browse the repository at this point in the history
This commit removes publishing policy from error classification. It was useful
when we tried to send some errors to the user and only log other errors.
Currently we try to send all errors to the user and log only database errors.
So there is no need to publishing policy because we just need to know if error
is a database error to log it.

Also removed self reference to `debug.log` from error messages. It was
previously possible for messages like "[o.n.b.v.r.ErrorReporter] Client
triggered an unexpected error [UnknownError]: null. See debug.log for more
details..." to appear in `debug.log`. This was caused by the fact that we
duplicate all user log messaged to internal log. See `StoreLogService` and `DuplicatingLogProvider` for more details.
  • Loading branch information
lutovich committed Feb 13, 2017
1 parent 68c71a7 commit f44fc7c
Show file tree
Hide file tree
Showing 5 changed files with 67 additions and 125 deletions.
Expand Up @@ -29,14 +29,13 @@
import org.neo4j.bolt.security.auth.AuthenticationResult; import org.neo4j.bolt.security.auth.AuthenticationResult;
import org.neo4j.bolt.v1.runtime.spi.BoltResult; import org.neo4j.bolt.v1.runtime.spi.BoltResult;
import org.neo4j.function.ThrowingConsumer; import org.neo4j.function.ThrowingConsumer;
import org.neo4j.graphdb.security.AuthorizationExpiredException;
import org.neo4j.graphdb.security.AuthProviderTimeoutException; import org.neo4j.graphdb.security.AuthProviderTimeoutException;
import org.neo4j.graphdb.security.AuthorizationExpiredException;
import org.neo4j.kernel.api.bolt.ManagedBoltStateMachine; import org.neo4j.kernel.api.bolt.ManagedBoltStateMachine;
import org.neo4j.kernel.api.exceptions.KernelException; import org.neo4j.kernel.api.exceptions.KernelException;
import org.neo4j.kernel.api.exceptions.Status; import org.neo4j.kernel.api.exceptions.Status;
import org.neo4j.kernel.api.exceptions.TransactionFailureException; import org.neo4j.kernel.api.exceptions.TransactionFailureException;


import static java.lang.String.format;
import static org.neo4j.kernel.api.security.AuthToken.PRINCIPAL; import static org.neo4j.kernel.api.security.AuthToken.PRINCIPAL;


/** /**
Expand Down Expand Up @@ -659,11 +658,7 @@ State resetMachine( BoltStateMachine machine ) throws BoltConnectionFatality


private static void fail( BoltStateMachine machine, Neo4jError neo4jError ) private static void fail( BoltStateMachine machine, Neo4jError neo4jError )
{ {
if ( neo4jError.status().code().classification() == Status.Classification.DatabaseError ) machine.spi.reportError( neo4jError );
{
machine.spi.reportError( neo4jError );
}

machine.ctx.markFailed( neo4jError ); machine.ctx.markFailed( neo4jError );
} }


Expand Down
Expand Up @@ -20,9 +20,12 @@
package org.neo4j.bolt.v1.runtime; package org.neo4j.bolt.v1.runtime;


import org.neo4j.kernel.impl.logging.LogService; import org.neo4j.kernel.impl.logging.LogService;
import org.neo4j.kernel.impl.logging.StoreLogService;
import org.neo4j.logging.DuplicatingLogProvider;
import org.neo4j.logging.Log; import org.neo4j.logging.Log;


import static java.lang.String.format; import static java.lang.String.format;
import static org.neo4j.kernel.api.exceptions.Status.Classification.DatabaseError;


/** /**
* Report received exceptions into the appropriate log (console or debug) and delivery stacktraces to debug.log. * Report received exceptions into the appropriate log (console or debug) and delivery stacktraces to debug.log.
Expand All @@ -44,24 +47,29 @@ class ErrorReporter
this.debugLog = debugLog; this.debugLog = debugLog;
} }


/**
* Writes logs about database errors.
* Short one-line message is written to both user and internal log.
* Large message with stacktrace (if available) is written to internal log.
*
* @param error the error to log.
* @see StoreLogService
* @see DuplicatingLogProvider
*/
public void report( Neo4jError error ) public void report( Neo4jError error )
{ {
if ( error.status().code().classification().shouldLog() ) if ( error.status().code().classification() == DatabaseError )
{ {
userLog.error( "Client triggered an unexpected error [%s]: %s. " + String message = format( "Client triggered an unexpected error [%s]: %s, reference %s.",
"See debug.log for more details, reference %s.",
error.status(), error.message(), error.reference() ); error.status(), error.message(), error.reference() );


// Writing to user log gets duplicated to the internal log
userLog.error( message );

// If cause/stacktrace is available write it to the internal log
if ( error.cause() != null ) if ( error.cause() != null )
{ {
debugLog.error( format( "Client triggered an unexpected error [%s]: %s, reference %s.", debugLog.error( message, error.cause() );
error.status(), error.message(), error.reference() ),
error.cause() );
}
else
{
debugLog.error( format( "Client triggered an unexpected error [%s]: %s, reference %s.",
error.status(), error.message(), error.reference() ) );
} }
} }
} }
Expand Down
Expand Up @@ -20,58 +20,37 @@
package org.neo4j.bolt.v1.runtime; package org.neo4j.bolt.v1.runtime;


import org.junit.Test; import org.junit.Test;
import org.neo4j.kernel.api.exceptions.Status;
import org.neo4j.logging.AssertableLogProvider;


import java.util.UUID; import java.util.UUID;


import org.neo4j.kernel.api.exceptions.Status;
import org.neo4j.logging.AssertableLogProvider;
import org.neo4j.logging.LogProvider;

import static org.mockito.Mockito.mock; import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.when; import static org.mockito.Mockito.when;


public class ErrorReporterTest public class ErrorReporterTest
{ {
@Test @Test
public void clientErrorShouldNotLog() throws Exception public void onlyDatabaseErrorsAreLogged()
{ {
// given
AssertableLogProvider userLog = new AssertableLogProvider(); AssertableLogProvider userLog = new AssertableLogProvider();
AssertableLogProvider internalLog = new AssertableLogProvider(); AssertableLogProvider internalLog = new AssertableLogProvider();
ErrorReporter reporter = ErrorReporter reporter = newErrorReporter( userLog, internalLog );
new ErrorReporter( userLog.getLog( "userLog" ), internalLog.getLog( "internalLog" ) );

for ( Status.Classification classification : Status.Classification.values() )
Status.Code code = mock( Status.Code.class ); {
Neo4jError error = Neo4jError.from( () -> code, "Should not be logged" ); if ( classification != Status.Classification.DatabaseError )
when( code.classification() ).thenReturn( Status.Classification.ClientError ); {

Status.Code code = newStatusCode( classification );
// when Neo4jError error = Neo4jError.from( () -> code, "Database error" );
reporter.report( error ); reporter.report( error );


// then userLog.assertNoLoggingOccurred();

internalLog.assertNoLoggingOccurred();
userLog.assertNoLoggingOccurred(); }
internalLog.assertNoLoggingOccurred(); }
}

@Test
public void clientNotificationShouldNotLog() throws Exception
{
// given
AssertableLogProvider userLog = new AssertableLogProvider();
AssertableLogProvider internalLog = new AssertableLogProvider();
ErrorReporter reporter =
new ErrorReporter( userLog.getLog( "userLog" ), internalLog.getLog( "internalLog" ) );

Status.Code code = mock( Status.Code.class );
Neo4jError error = Neo4jError.from( () -> code, "Should not be logged" );
when( code.classification() ).thenReturn( Status.Classification.ClientNotification );

// when
reporter.report( error );

// then

userLog.assertNoLoggingOccurred();
internalLog.assertNoLoggingOccurred();
} }


@Test @Test
Expand All @@ -80,12 +59,9 @@ public void databaseErrorShouldLogFullMessageInDebugLogAndHelpfulPointerInUserLo
// given // given
AssertableLogProvider userLog = new AssertableLogProvider(); AssertableLogProvider userLog = new AssertableLogProvider();
AssertableLogProvider internalLog = new AssertableLogProvider(); AssertableLogProvider internalLog = new AssertableLogProvider();
ErrorReporter reporter = ErrorReporter reporter = newErrorReporter( userLog, internalLog );
new ErrorReporter( userLog.getLog( "userLog" ), internalLog.getLog( "internalLog" ) );


Status.Code code = mock( Status.Code.class ); Neo4jError error = Neo4jError.fatalFrom( new TestDatabaseError() );
Neo4jError error = Neo4jError.from( () -> code, "Database error" );
when( code.classification() ).thenReturn( Status.Classification.DatabaseError );
UUID reference = error.reference(); UUID reference = error.reference();


// when // when
Expand All @@ -100,29 +76,29 @@ public void databaseErrorShouldLogFullMessageInDebugLogAndHelpfulPointerInUserLo
internalLog.assertContainsLogCallContaining( "Database error" ); internalLog.assertContainsLogCallContaining( "Database error" );
} }


@Test private static ErrorReporter newErrorReporter( LogProvider userLog, LogProvider internalLog )
public void transientErrorShouldLogFullMessageInDebugLogAndHelpfulPointerInUserLog() throws Exception
{ {
// given return new ErrorReporter( userLog.getLog( "userLog" ), internalLog.getLog( "internalLog" ) );
AssertableLogProvider userLog = new AssertableLogProvider(); }
AssertableLogProvider internalLog = new AssertableLogProvider();
ErrorReporter reporter =
new ErrorReporter( userLog.getLog( "userLog" ), internalLog.getLog( "internalLog" ) );


private static Status.Code newStatusCode( Status.Classification classification )
{
Status.Code code = mock( Status.Code.class ); Status.Code code = mock( Status.Code.class );
Neo4jError error = Neo4jError.from( () -> code, "Transient error" ); when( code.classification() ).thenReturn( classification );
when( code.classification() ).thenReturn( Status.Classification.TransientError ); return code;
UUID reference = error.reference(); }

// when
reporter.report( error );

// then
userLog.assertContainsLogCallContaining( "Client triggered an unexpected error" );
userLog.assertContainsLogCallContaining( reference.toString() );
userLog.assertContainsLogCallContaining( "Transient error" );


internalLog.assertContainsLogCallContaining( reference.toString() ); private static class TestDatabaseError extends RuntimeException implements Status.HasStatus
internalLog.assertContainsLogCallContaining( "Transient error" ); {
TestDatabaseError()
{
super( "Database error" );
}

@Override
public Status status()
{
return () -> newStatusCode( Status.Classification.DatabaseError );
}
} }
} }
Expand Up @@ -21,15 +21,13 @@


import org.junit.Test; import org.junit.Test;


import org.neo4j.cypher.LoadExternalResourceException;
import org.neo4j.graphdb.DatabaseShutdownException; import org.neo4j.graphdb.DatabaseShutdownException;
import org.neo4j.kernel.DeadlockDetectedException; import org.neo4j.kernel.DeadlockDetectedException;
import org.neo4j.kernel.api.exceptions.Status; import org.neo4j.kernel.api.exceptions.Status;


import static java.util.Arrays.asList; import static java.util.Arrays.asList;
import static junit.framework.TestCase.assertEquals; import static junit.framework.TestCase.assertEquals;
import static org.hamcrest.CoreMatchers.equalTo; import static org.hamcrest.CoreMatchers.equalTo;
import static org.hamcrest.CoreMatchers.is;
import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.MatcherAssert.assertThat;


public class Neo4jErrorTest public class Neo4jErrorTest
Expand All @@ -55,16 +53,6 @@ public void shouldConvertDeadlockException() throws Throwable
assertEquals( error.status(), Status.Transaction.DeadlockDetected ); assertEquals( error.status(), Status.Transaction.DeadlockDetected );
} }


@Test
public void loadExternalResourceShouldNotReferToLog()
{
// Given
Neo4jError error = Neo4jError.from( new LoadExternalResourceException( "foo", null ) );

// Then
assertThat( error.status().code().classification().shouldLog(), is( false ) );
}

@Test @Test
public void shouldSetStatusToDatabaseUnavailableOnDatabaseShutdownException() public void shouldSetStatusToDatabaseUnavailableOnDatabaseShutdownException()
{ {
Expand Down
Expand Up @@ -606,55 +606,35 @@ public int hashCode()
enum Classification enum Classification
{ {
/** The Client sent a bad request - changing the request might yield a successful outcome. */ /** The Client sent a bad request - changing the request might yield a successful outcome. */
ClientError( TransactionEffect.ROLLBACK, PublishingPolicy.REPORTS_TO_CLIENT, ClientError( TransactionEffect.ROLLBACK,
"The Client sent a bad request - changing the request might yield a successful outcome."), "The Client sent a bad request - changing the request might yield a successful outcome."),
/** There are notifications about the request sent by the client.*/ /** There are notifications about the request sent by the client.*/
ClientNotification( TransactionEffect.NONE, PublishingPolicy.REPORTS_TO_CLIENT, ClientNotification( TransactionEffect.NONE,
"There are notifications about the request sent by the client." ), "There are notifications about the request sent by the client." ),


/** The database cannot service the request right now, retrying later might yield a successful outcome. */ /** The database cannot service the request right now, retrying later might yield a successful outcome. */
TransientError( TransactionEffect.ROLLBACK, PublishingPolicy.REPORTS_TO_CLIENT_AND_LOG, TransientError( TransactionEffect.ROLLBACK,
"The database cannot service the request right now, retrying later might yield a successful outcome. "), "The database cannot service the request right now, retrying later might yield a successful outcome. "),


// Implementation note: These are a sharp tool, database error signals // Implementation note: These are a sharp tool, database error signals
// that something is *seriously* wrong, and will prompt the user to send // that something is *seriously* wrong, and will prompt the user to send
// an error report back to us. Only use this if the code path you are // an error report back to us. Only use this if the code path you are
// at would truly indicate the database is in a broken or bug-induced state. // at would truly indicate the database is in a broken or bug-induced state.
/** The database failed to service the request. */ /** The database failed to service the request. */
DatabaseError( TransactionEffect.ROLLBACK, PublishingPolicy.REFERS_TO_LOG, DatabaseError( TransactionEffect.ROLLBACK,
"The database failed to service the request. " ); "The database failed to service the request. " );


private enum TransactionEffect private enum TransactionEffect
{ {
ROLLBACK, NONE, ROLLBACK, NONE,
} }


private enum PublishingPolicy
{
REPORTS_TO_CLIENT( false ), REPORTS_TO_CLIENT_AND_LOG( true ), REFERS_TO_LOG( true );

private final boolean shouldLog;

PublishingPolicy( boolean shouldLog )
{
this.shouldLog = shouldLog;
}

boolean shouldLog()
{
return shouldLog;
}

}

private final boolean rollbackTransaction; private final boolean rollbackTransaction;
private final boolean shouldLog;
private final String description; private final String description;


Classification( TransactionEffect transactionEffect, PublishingPolicy publishingPolicy, String description ) Classification( TransactionEffect transactionEffect, String description )
{ {
this.description = description; this.description = description;
this.shouldLog = publishingPolicy.shouldLog();
this.rollbackTransaction = transactionEffect == TransactionEffect.ROLLBACK; this.rollbackTransaction = transactionEffect == TransactionEffect.ROLLBACK;
} }


Expand All @@ -663,11 +643,6 @@ public boolean rollbackTransaction()
return rollbackTransaction; return rollbackTransaction;
} }


public boolean shouldLog()
{
return shouldLog;
}

public String description() public String description()
{ {
return description; return description;
Expand Down

0 comments on commit f44fc7c

Please sign in to comment.