Skip to content

Commit

Permalink
Include error reference in both user and debug logs.
Browse files Browse the repository at this point in the history 
The unique reference allows the user to locate a detailed stack trace
that corresponds to a briefer messages in the user log, and to the short
message sent back to the client.
  • Loading branch information
@apcj
apcj committed Apr 20, 2016
1 parent 74a1a95 commit bea3a2b
Show file tree
Hide file tree
Showing 5 changed files with 103 additions and 104 deletions.
17 changes: 8 additions & 9 deletions .../bolt/src/main/java/org/neo4j/bolt/v1/messaging/msgprocess/MessageProcessingCallback.java
View file
Expand Up @@ -34,20 +34,19 @@ public class MessageProcessingCallback<T> extends Session.Callback.Adapter<T,Voi
public static void publishError( MessageHandler<IOException> out, Neo4jError error )
throws IOException
{
if ( error.status().code().classification().publishable() )
if ( error.status().code().classification().refersToLog() )
{
// If publishable, we forward the message as-is to the user.
out.handleFailureMessage( error.status(), error.message() );
}
else
{
// If not publishable, we only return an error reference to the user. This must
// be cross-referenced with the log files for full error detail. This feature
// exists to improve security so that sensitive information is not leaked.
// If not intended for client, we only return an error reference. This must
// be cross-referenced with the log files for full error detail.
out.handleFailureMessage( error.status(), String.format(
"An unexpected failure occurred, see details in the database " +
"logs, reference number %s.", error.reference() ) );
}
else
{
// If intended for client, we forward the message as-is.
out.handleFailureMessage( error.status(), error.message() );
}
}

protected final Log log;
Expand Down
22 changes: 7 additions & 15 deletions community/bolt/src/main/java/org/neo4j/bolt/v1/runtime/internal/ErrorReporter.java
View file
Expand Up @@ -19,7 +19,6 @@
*/
package org.neo4j.bolt.v1.runtime.internal;

import org.neo4j.helpers.Exceptions;
import org.neo4j.kernel.impl.logging.LogService;
import org.neo4j.logging.Log;

Expand All @@ -30,8 +29,6 @@
*/
class ErrorReporter
{
private static final String EMPTY_STRING = "";

private final Log userLog;
private final Log debugLog;

Expand All @@ -49,20 +46,15 @@ class ErrorReporter

public void report( Neo4jError error )
{
if ( !error.status().code().classification().publishable() )
if ( error.status().code().classification().refersToLog() )
{
userLog.error( format( "Client triggered an unexpected error: %s. See debug.log for more details.",
error.cause().getMessage() ) );
}
userLog.error( "Client triggered an unexpected error [%s]: %s. " +
"See debug.log for more details, reference %s.",
error.status(), error.message(), error.reference() );

if ( somethingToLog( error ) )
{
debugLog.error( Exceptions.stringify( error.cause() ) );
debugLog.error( format( "Client triggered an unexpected error [%s]: %s, reference %s.",
error.status(), error.message(), error.reference() ),
error.cause() );
}
}

private boolean somethingToLog( Neo4jError error )
{
return error != null && error.cause() != null;
}
}
124 changes: 64 additions & 60 deletions community/bolt/src/test/java/org/neo4j/bolt/v1/runtime/internal/ErrorReporterTest.java
View file
Expand Up @@ -19,110 +19,114 @@
*/
package org.neo4j.bolt.v1.runtime.internal;

import java.util.UUID;

import org.junit.Test;

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

import static org.hamcrest.CoreMatchers.equalTo;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.mockito.Matchers.contains;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.when;

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


Throwable cause = new Throwable( "Hello World" );
Neo4jError error = Neo4jError.from( cause );
Status.Code code = mock( Status.Code.class );
Neo4jError error = new Neo4jError( () -> code, "Should not be logged" );
when( code.classification() ).thenReturn( Status.Classification.ClientError );

// when
reporter.report( error );

// then
verify( userLog ).error( "Client triggered an unexpected error: Hello World. See debug.log for more details." );
verify( internalLog ).error( contains( "java.lang.Throwable: Hello World" ) );

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

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

Throwable cause = new Throwable( "This is not an error we know how to handle." );
Neo4jError error = Neo4jError.from( cause );

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

// when
reporter.report( error );

// Then
assertThat( error.status(), equalTo( (Status) Status.General.UnknownError ) );
provider.assertContainsMessageContaining( error.cause().getMessage() );
// then

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


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

Throwable cause = new OutOfMemoryError( "memory is fading" );
Neo4jError error = Neo4jError.from( cause );
Status.Code code = mock( Status.Code.class );
Neo4jError error = new Neo4jError( () -> code, "Database error" );
when( code.classification() ).thenReturn( Status.Classification.DatabaseError );
UUID reference = error.reference();

// When
// when
reporter.report( error );

// Then
assertThat( error.status(), equalTo( (Status) Status.General.OutOfMemoryError ) );
assertThat( error.message(),
equalTo( "There is not enough memory to perform the current task. Please try increasing " +
"'dbms.memory.heap.max_size' in the process wrapper configuration (normally in " +
"'conf/neo4j-wrapper" +
".conf' or, if you are using Neo4j Desktop, found through the user interface) or if you are " +
"running an embedded " +
"installation increase the heap by using '-Xmx' command line flag, and then restart the " +
"database." ) );
provider.assertContainsMessageContaining( cause.getClass().getName() );
// then
userLog.assertContainsLogCallContaining( "Client triggered an unexpected error" );
userLog.assertContainsLogCallContaining( reference.toString() );
userLog.assertContainsLogCallContaining( "Database error" );

internalLog.assertContainsLogCallContaining( reference.toString() );
internalLog.assertContainsLogCallContaining( "Database error" );
}

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

Throwable cause = new StackOverflowError( "some rewriter is probably not tail recursive" );
Neo4jError error = Neo4jError.from( cause );
Status.Code code = mock( Status.Code.class );
Neo4jError error = new Neo4jError( () -> code, "Transient error" );
when( code.classification() ).thenReturn( Status.Classification.TransientError );
UUID reference = error.reference();

// When
// when
reporter.report( error );

// Then
assertThat( error.status(), equalTo( (Status) Status.General.StackOverFlowError ) );
assertThat( error.message(), equalTo(
"There is not enough stack size to perform the current task. This is generally considered to be a " +
"database error, so please contact Neo4j support. You could try increasing the stack size: " +
"for example to set the stack size to 2M, add `dbms.jvm.additional=-Xss2M' to " +
"in the process wrapper configuration (normally in 'conf/neo4j-wrapper.conf' or, if you are " +
"using " +
"Neo4j Desktop, found through the user interface) or if you are running an embedded " +
"installation " +
"just add -Xss2M as command line flag." ) );
provider.assertContainsMessageContaining( cause.getClass().getName() );
// then
userLog.assertContainsLogCallContaining( "Client triggered an unexpected error" );
userLog.assertContainsLogCallContaining( reference.toString() );
userLog.assertContainsLogCallContaining( "Transient error" );

internalLog.assertContainsLogCallContaining( reference.toString() );
internalLog.assertContainsLogCallContaining( "Transient error" );
}
}
13 changes: 13 additions & 0 deletions community/bolt/src/test/java/org/neo4j/bolt/v1/runtime/internal/Neo4jErrorTest.java
View file
Expand Up @@ -25,9 +25,22 @@
import org.neo4j.kernel.api.exceptions.Status;

import static junit.framework.TestCase.assertEquals;
import static org.hamcrest.CoreMatchers.equalTo;
import static org.hamcrest.MatcherAssert.assertThat;

public class Neo4jErrorTest
{
@Test
public void shouldAssignUnknownStatusToUnpredictedException()
{
// Given
Throwable cause = new Throwable( "This is not an error we know how to handle." );
Neo4jError error = Neo4jError.from( cause );

// Then
assertThat( error.status(), equalTo( (Status) Status.General.UnknownError ) );
}

@Test
public void shouldConvertDeadlockException() throws Throwable
{
Expand Down
31 changes: 11 additions & 20 deletions community/common/src/main/java/org/neo4j/kernel/api/exceptions/Status.java
View file
Expand Up @@ -550,52 +550,43 @@ public int hashCode()
enum Classification
{
/** The Client sent a bad request - changing the request might yield a successful outcome. */
ClientError( TransactionEffect.ROLLBACK, PublishingPolicy.PUBLISHABLE,
ClientError( TransactionEffect.ROLLBACK, PublishingPolicy.REPORTS_TO_CLIENT,
"The Client sent a bad request - changing the request might yield a successful outcome."),
/** There are notifications about the request sent by the client.*/
ClientNotification( TransactionEffect.NONE, PublishingPolicy.PUBLISHABLE,
ClientNotification( TransactionEffect.NONE, PublishingPolicy.REPORTS_TO_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. */
TransientError( TransactionEffect.ROLLBACK, PublishingPolicy.PUBLISHABLE,
TransientError( TransactionEffect.ROLLBACK, PublishingPolicy.REFERS_TO_LOG,
"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
// 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
// at would truly indicate the database is in a broken or bug-induced state.
/** The database failed to service the request. */
DatabaseError( TransactionEffect.ROLLBACK, PublishingPolicy.INTERNAL,
"The database failed to service the request. " ),

;
DatabaseError( TransactionEffect.ROLLBACK, PublishingPolicy.REFERS_TO_LOG,
"The database failed to service the request. " );

private enum TransactionEffect
{
ROLLBACK, NONE,
}

/**
* A PUBLISHABLE error/warning is one which allows sending a meaningful error message to
* the client with the expectation that the user will be able to take any necessary action
* to resolve the error. INTERNAL errors are more sensitive and may not be resolvable by
* the user - these will be logged and only a reference will be forwarded to the user.
* This is a security feature to avoid leaking potentially sensitive information to end
* users.
*/

private enum PublishingPolicy
{
PUBLISHABLE, INTERNAL,
REPORTS_TO_CLIENT, REFERS_TO_LOG
}

private final boolean rollbackTransaction;
private final boolean publishable;
private final boolean refersToLog;
private final String description;

Classification( TransactionEffect transactionEffect, PublishingPolicy publishingPolicy, String description )
{
this.description = description;
this.publishable = publishingPolicy == PublishingPolicy.PUBLISHABLE;
this.refersToLog = publishingPolicy == PublishingPolicy.REFERS_TO_LOG;
this.rollbackTransaction = transactionEffect == TransactionEffect.ROLLBACK;
}

Expand All @@ -604,9 +595,9 @@ public boolean rollbackTransaction()
return rollbackTransaction;
}

public boolean publishable()
public boolean refersToLog()
{
return publishable;
return refersToLog;
}

public String description()
Expand Down

0 comments on commit bea3a2b

Please sign in to comment.