Add channel error logger for channel errors (#1039) (#1053)

injectives · web-flow · commit a110c6b37c1d · 2021-11-01T09:49:01.000Z
The new logger provides a dedicated facility for channel error logging in debug and trace modes.
diff --git a/driver/src/main/java/org/neo4j/driver/internal/async/connection/HandshakeHandler.java b/driver/src/main/java/org/neo4j/driver/internal/async/connection/HandshakeHandler.java
@@ -27,16 +27,16 @@
 import java.util.List;
 import javax.net.ssl.SSLHandshakeException;
 
+import org.neo4j.driver.Logging;
+import org.neo4j.driver.exceptions.ClientException;
+import org.neo4j.driver.exceptions.SecurityException;
+import org.neo4j.driver.exceptions.ServiceUnavailableException;
 import org.neo4j.driver.internal.logging.ChannelActivityLogger;
+import org.neo4j.driver.internal.logging.ChannelErrorLogger;
 import org.neo4j.driver.internal.messaging.BoltProtocol;
 import org.neo4j.driver.internal.messaging.BoltProtocolVersion;
 import org.neo4j.driver.internal.messaging.MessageFormat;
 import org.neo4j.driver.internal.util.ErrorUtil;
-import org.neo4j.driver.Logger;
-import org.neo4j.driver.Logging;
-import org.neo4j.driver.exceptions.ClientException;
-import org.neo4j.driver.exceptions.SecurityException;
-import org.neo4j.driver.exceptions.ServiceUnavailableException;
 
 import static org.neo4j.driver.internal.async.connection.BoltProtocolUtil.NO_PROTOCOL_VERSION;
 import static org.neo4j.driver.internal.messaging.BoltProtocolVersion.isHttp;
@@ -48,10 +48,11 @@ public class HandshakeHandler extends ReplayingDecoder<Void>
     private final Logging logging;
 
     private boolean failed;
-    private Logger log;
+    private ChannelActivityLogger log;
+    private ChannelErrorLogger errorLog;
 
     public HandshakeHandler( ChannelPipelineBuilder pipelineBuilder, ChannelPromise handshakeCompletedPromise,
-            Logging logging )
+                             Logging logging )
     {
         this.pipelineBuilder = pipelineBuilder;
         this.handshakeCompletedPromise = handshakeCompletedPromise;
@@ -62,6 +63,7 @@ public HandshakeHandler( ChannelPipelineBuilder pipelineBuilder, ChannelPromise
     public void handlerAdded( ChannelHandlerContext ctx )
     {
         log = new ChannelActivityLogger( ctx.channel(), logging, getClass() );
+        errorLog = new ChannelErrorLogger( ctx.channel(), logging );
     }
 
     @Override
@@ -89,7 +91,7 @@ public void exceptionCaught( ChannelHandlerContext ctx, Throwable error )
     {
         if ( failed )
         {
-            log.warn( "Another fatal error occurred in the pipeline", error );
+            errorLog.traceOrDebug( "Another fatal error occurred in the pipeline", error );
         }
         else
         {
diff --git a/driver/src/main/java/org/neo4j/driver/internal/async/inbound/ChannelErrorHandler.java b/driver/src/main/java/org/neo4j/driver/internal/async/inbound/ChannelErrorHandler.java
@@ -24,11 +24,11 @@
 
 import java.io.IOException;
 
-import org.neo4j.driver.Logger;
 import org.neo4j.driver.Logging;
 import org.neo4j.driver.exceptions.ConnectionReadTimeoutException;
 import org.neo4j.driver.exceptions.ServiceUnavailableException;
 import org.neo4j.driver.internal.logging.ChannelActivityLogger;
+import org.neo4j.driver.internal.logging.ChannelErrorLogger;
 import org.neo4j.driver.internal.util.ErrorUtil;
 
 import static java.util.Objects.requireNonNull;
@@ -40,7 +40,8 @@ public class ChannelErrorHandler extends ChannelInboundHandlerAdapter
     private final Logging logging;
 
     private InboundMessageDispatcher messageDispatcher;
-    private Logger log;
+    private ChannelActivityLogger log;
+    private ChannelErrorLogger errorLog;
     private boolean failed;
 
     public ChannelErrorHandler( Logging logging )
@@ -53,6 +54,7 @@ public void handlerAdded( ChannelHandlerContext ctx )
     {
         messageDispatcher = requireNonNull( messageDispatcher( ctx.channel() ) );
         log = new ChannelActivityLogger( ctx.channel(), logging, getClass() );
+        errorLog = new ChannelErrorLogger( ctx.channel(), logging );
     }
 
     @Override
@@ -90,7 +92,7 @@ public void exceptionCaught( ChannelHandlerContext ctx, Throwable error )
     {
         if ( failed )
         {
-            log.warn( "Another fatal error occurred in the pipeline", error );
+            errorLog.traceOrDebug( "Another fatal error occurred in the pipeline", error );
         }
         else
         {
@@ -104,7 +106,7 @@ private void logUnexpectedErrorWarning( Throwable error )
     {
         if ( !(error instanceof ConnectionReadTimeoutException) )
         {
-            log.warn( "Fatal error occurred in the pipeline", error );
+            errorLog.traceOrDebug( "Fatal error occurred in the pipeline", error );
         }
     }
 
diff --git a/driver/src/main/java/org/neo4j/driver/internal/async/inbound/InboundMessageDispatcher.java b/driver/src/main/java/org/neo4j/driver/internal/async/inbound/InboundMessageDispatcher.java
@@ -32,6 +32,7 @@
 import org.neo4j.driver.exceptions.ClientException;
 import org.neo4j.driver.internal.handlers.ResetResponseHandler;
 import org.neo4j.driver.internal.logging.ChannelActivityLogger;
+import org.neo4j.driver.internal.logging.ChannelErrorLogger;
 import org.neo4j.driver.internal.messaging.ResponseMessageHandler;
 import org.neo4j.driver.internal.spi.ResponseHandler;
 import org.neo4j.driver.internal.util.ErrorUtil;
@@ -46,6 +47,7 @@ public class InboundMessageDispatcher implements ResponseMessageHandler
     private final Channel channel;
     private final Queue<ResponseHandler> handlers = new LinkedList<>();
     private final Logger log;
+    private final ChannelErrorLogger errorLog;
 
     private volatile boolean gracefullyClosed;
     private Throwable currentError;
@@ -58,6 +60,7 @@ public InboundMessageDispatcher( Channel channel, Logging logging )
     {
         this.channel = requireNonNull( channel );
         this.log = new ChannelActivityLogger( channel, logging, getClass() );
+        this.errorLog = new ChannelErrorLogger( channel, logging );
     }
 
     public void enqueue( ResponseHandler handler )
@@ -198,7 +201,7 @@ public void handleChannelError( Throwable error )
             handler.onFailure( currentError );
         }
 
-        log.debug( "Closing channel because of a failure", error );
+        errorLog.traceOrDebug( "Closing channel because of a failure", error );
         channel.close();
     }
 
@@ -287,4 +290,10 @@ Logger getLog()
     {
         return log;
     }
+
+    //    For testing only
+    Logger getErrorLog()
+    {
+        return errorLog;
+    }
 }
diff --git a/driver/src/main/java/org/neo4j/driver/internal/logging/ChannelErrorLogger.java b/driver/src/main/java/org/neo4j/driver/internal/logging/ChannelErrorLogger.java
@@ -0,0 +1,50 @@
+/*
+ * Copyright (c) "Neo4j"
+ * Neo4j Sweden AB [http://neo4j.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 io.netty.channel.Channel;
+
+import org.neo4j.driver.Logging;
+
+/**
+ * Dedicated logger for channel error logging.
+ * <p>
+ * It keeps messages shorter in debug mode and provides more details in trace mode.
+ */
+public class ChannelErrorLogger extends ChannelActivityLogger
+{
+    private static final String DEBUG_MESSAGE_FORMAT = "%s (%s)";
+
+    public ChannelErrorLogger( Channel channel, Logging logging )
+    {
+        super( channel, logging, ChannelErrorLogger.class );
+    }
+
+    public void traceOrDebug( String message, Throwable error )
+    {
+        if ( isTraceEnabled() )
+        {
+            trace( message, error );
+        }
+        else
+        {
+            debug( String.format( DEBUG_MESSAGE_FORMAT, message, error.getClass() ) );
+        }
+    }
+}
diff --git a/driver/src/test/java/org/neo4j/driver/internal/async/inbound/InboundMessageDispatcherTest.java b/driver/src/test/java/org/neo4j/driver/internal/async/inbound/InboundMessageDispatcherTest.java
@@ -38,6 +38,7 @@
 import org.neo4j.driver.exceptions.ClientException;
 import org.neo4j.driver.exceptions.Neo4jException;
 import org.neo4j.driver.internal.logging.ChannelActivityLogger;
+import org.neo4j.driver.internal.logging.ChannelErrorLogger;
 import org.neo4j.driver.internal.messaging.Message;
 import org.neo4j.driver.internal.messaging.response.FailureMessage;
 import org.neo4j.driver.internal.messaging.response.IgnoredMessage;
@@ -56,6 +57,7 @@
 import static org.mockito.ArgumentMatchers.anyBoolean;
 import static org.mockito.ArgumentMatchers.anyString;
 import static org.mockito.ArgumentMatchers.argThat;
+import static org.mockito.ArgumentMatchers.contains;
 import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.inOrder;
 import static org.mockito.Mockito.mock;
@@ -378,6 +380,8 @@ void shouldCreateChannelActivityLoggerAndLogDebugMessageOnMessageHandling( Class
         Logger logger = mock( Logger.class );
         when( logger.isDebugEnabled() ).thenReturn( true );
         when( logging.getLog( InboundMessageDispatcher.class.getSimpleName() ) ).thenReturn( logger );
+        ChannelErrorLogger errorLogger = mock( ChannelErrorLogger.class );
+        when( logging.getLog( ChannelErrorLogger.class.getSimpleName() ) ).thenReturn( errorLogger );
         InboundMessageDispatcher dispatcher = new InboundMessageDispatcher( channel, logging );
         ResponseHandler handler = mock( ResponseHandler.class );
         dispatcher.enqueue( handler );
@@ -406,18 +410,22 @@ else if ( IgnoredMessage.class.isAssignableFrom( message ) )
 
         // THEN
         assertTrue( dispatcher.getLog() instanceof ChannelActivityLogger );
+        assertTrue( dispatcher.getErrorLog() instanceof ChannelErrorLogger );
         verify( logger ).debug( anyString(), any( Object.class ) );
     }
 
     @Test
-    void shouldCreateChannelActivityLoggerAndLogDebugMessageOnChannelError()
+    void shouldCreateChannelErrorLoggerAndLogDebugMessageOnChannelError()
     {
         // GIVEN
         Channel channel = newChannelMock();
         Logging logging = mock( Logging.class );
         Logger logger = mock( Logger.class );
         when( logger.isDebugEnabled() ).thenReturn( true );
         when( logging.getLog( InboundMessageDispatcher.class.getSimpleName() ) ).thenReturn( logger );
+        ChannelErrorLogger errorLogger = mock( ChannelErrorLogger.class );
+        when( errorLogger.isDebugEnabled() ).thenReturn( true );
+        when( logging.getLog( ChannelErrorLogger.class.getSimpleName() ) ).thenReturn( errorLogger );
         InboundMessageDispatcher dispatcher = new InboundMessageDispatcher( channel, logging );
         ResponseHandler handler = mock( ResponseHandler.class );
         dispatcher.enqueue( handler );
@@ -428,7 +436,8 @@ void shouldCreateChannelActivityLoggerAndLogDebugMessageOnChannelError()
 
         // THEN
         assertTrue( dispatcher.getLog() instanceof ChannelActivityLogger );
-        verify( logger ).debug( anyString(), eq( throwable ) );
+        assertTrue( dispatcher.getErrorLog() instanceof ChannelErrorLogger );
+        verify( errorLogger ).debug( contains( throwable.getClass().toString() ) );
     }
 
     private static void verifyFailure( ResponseHandler handler )

Original file line number	Diff line number	Diff line change
`@@ -24,11 +24,11 @@`
`24`	`24`
`25`	`25`	`import java.io.IOException;`
`26`	`26`
`27`		`-import org.neo4j.driver.Logger;`
`28`	`27`	`import org.neo4j.driver.Logging;`
`29`	`28`	`import org.neo4j.driver.exceptions.ConnectionReadTimeoutException;`
`30`	`29`	`import org.neo4j.driver.exceptions.ServiceUnavailableException;`
`31`	`30`	`import org.neo4j.driver.internal.logging.ChannelActivityLogger;`
	`31`	`+import org.neo4j.driver.internal.logging.ChannelErrorLogger;`
`32`	`32`	`import org.neo4j.driver.internal.util.ErrorUtil;`
`33`	`33`
`34`	`34`	`import static java.util.Objects.requireNonNull;`
`@@ -40,7 +40,8 @@ public class ChannelErrorHandler extends ChannelInboundHandlerAdapter`
`40`	`40`	`private final Logging logging;`
`41`	`41`
`42`	`42`	`private InboundMessageDispatcher messageDispatcher;`
`43`		`- private Logger log;`
	`43`	`+ private ChannelActivityLogger log;`
	`44`	`+ private ChannelErrorLogger errorLog;`
`44`	`45`	`private boolean failed;`
`45`	`46`
`46`	`47`	`public ChannelErrorHandler( Logging logging )`
`@@ -53,6 +54,7 @@ public void handlerAdded( ChannelHandlerContext ctx )`
`53`	`54`	`{`
`54`	`55`	`messageDispatcher = requireNonNull( messageDispatcher( ctx.channel() ) );`
`55`	`56`	`log = new ChannelActivityLogger( ctx.channel(), logging, getClass() );`
	`57`	`+ errorLog = new ChannelErrorLogger( ctx.channel(), logging );`
`56`	`58`	`}`
`57`	`59`
`58`	`60`	`@Override`
`@@ -90,7 +92,7 @@ public void exceptionCaught( ChannelHandlerContext ctx, Throwable error )`
`90`	`92`	`{`
`91`	`93`	`if ( failed )`
`92`	`94`	`{`
`93`		`- log.warn( "Another fatal error occurred in the pipeline", error );`
	`95`	`+ errorLog.traceOrDebug( "Another fatal error occurred in the pipeline", error );`
`94`	`96`	`}`
`95`	`97`	`else`
`96`	`98`	`{`
`@@ -104,7 +106,7 @@ private void logUnexpectedErrorWarning( Throwable error )`
`104`	`106`	`{`
`105`	`107`	`if ( !(error instanceof ConnectionReadTimeoutException) )`
`106`	`108`	`{`
`107`		`- log.warn( "Fatal error occurred in the pipeline", error );`
	`109`	`+ errorLog.traceOrDebug( "Fatal error occurred in the pipeline", error );`
`108`	`110`	`}`
`109`	`111`	`}`
`110`	`112`
Original file line number	Diff line number	Diff line change
`@@ -32,6 +32,7 @@`
`32`	`32`	`import org.neo4j.driver.exceptions.ClientException;`
`33`	`33`	`import org.neo4j.driver.internal.handlers.ResetResponseHandler;`
`34`	`34`	`import org.neo4j.driver.internal.logging.ChannelActivityLogger;`
	`35`	`+import org.neo4j.driver.internal.logging.ChannelErrorLogger;`
`35`	`36`	`import org.neo4j.driver.internal.messaging.ResponseMessageHandler;`
`36`	`37`	`import org.neo4j.driver.internal.spi.ResponseHandler;`
`37`	`38`	`import org.neo4j.driver.internal.util.ErrorUtil;`
`@@ -46,6 +47,7 @@ public class InboundMessageDispatcher implements ResponseMessageHandler`
`46`	`47`	`private final Channel channel;`
`47`	`48`	`private final Queue<ResponseHandler> handlers = new LinkedList<>();`
`48`	`49`	`private final Logger log;`
	`50`	`+ private final ChannelErrorLogger errorLog;`
`49`	`51`
`50`	`52`	`private volatile boolean gracefullyClosed;`
`51`	`53`	`private Throwable currentError;`
`@@ -58,6 +60,7 @@ public InboundMessageDispatcher( Channel channel, Logging logging )`
`58`	`60`	`{`
`59`	`61`	`this.channel = requireNonNull( channel );`
`60`	`62`	`this.log = new ChannelActivityLogger( channel, logging, getClass() );`
	`63`	`+ this.errorLog = new ChannelErrorLogger( channel, logging );`
`61`	`64`	`}`
`62`	`65`
`63`	`66`	`public void enqueue( ResponseHandler handler )`
`@@ -198,7 +201,7 @@ public void handleChannelError( Throwable error )`
`198`	`201`	`handler.onFailure( currentError );`
`199`	`202`	`}`
`200`	`203`
`201`		`- log.debug( "Closing channel because of a failure", error );`
	`204`	`+ errorLog.traceOrDebug( "Closing channel because of a failure", error );`
`202`	`205`	`channel.close();`
`203`	`206`	`}`
`204`	`207`
`@@ -287,4 +290,10 @@ Logger getLog()`
`287`	`290`	`{`
`288`	`291`	`return log;`
`289`	`292`	`}`
	`293`	`+`
	`294`	`+ // For testing only`
	`295`	`+ Logger getErrorLog()`
	`296`	`+ {`
	`297`	`+ return errorLog;`
	`298`	`+ }`
`290`	`299`	`}`