From 513b99dc10432bcbf85a69802cd5deb61f78e9bc Mon Sep 17 00:00:00 2001 From: Ali Ince Date: Fri, 7 Dec 2018 13:10:53 +0000 Subject: [PATCH] Handle exceptions on transport selection stage with less noise --- .../transport/SocketTransportHandler.java | 23 ++++- .../transport/TransportSelectionHandler.java | 28 ++++++ .../SocketTransportHandlerTest.java | 32 +++++-- .../TransportSelectionHandlerTest.java | 85 +++++++++++++++++++ 4 files changed, 159 insertions(+), 9 deletions(-) rename community/bolt/src/test/java/org/neo4j/bolt/{v1/transport/socket => transport}/SocketTransportHandlerTest.java (86%) create mode 100644 community/bolt/src/test/java/org/neo4j/bolt/transport/TransportSelectionHandlerTest.java diff --git a/community/bolt/src/main/java/org/neo4j/bolt/transport/SocketTransportHandler.java b/community/bolt/src/main/java/org/neo4j/bolt/transport/SocketTransportHandler.java index 2a11e0436bf61..3a6de842dd3e5 100644 --- a/community/bolt/src/main/java/org/neo4j/bolt/transport/SocketTransportHandler.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/transport/SocketTransportHandler.java @@ -23,6 +23,7 @@ import io.netty.channel.ChannelHandlerContext; import io.netty.channel.ChannelInboundHandlerAdapter; +import org.neo4j.helpers.Exceptions; import org.neo4j.logging.Log; import org.neo4j.logging.LogProvider; @@ -83,8 +84,26 @@ public void handlerRemoved( ChannelHandlerContext ctx ) throws Exception @Override public void exceptionCaught( ChannelHandlerContext ctx, Throwable cause ) throws Exception { - log.error( "Fatal error occurred when handling a client connection: " + cause.getMessage(), cause ); - close( ctx ); + try + { + // Netty throws a NativeIoException on connection reset - directly importing that class + // caused a host of linking errors, because it depends on JNI to work. Hence, we just + // test on the message we know we'll get. + if ( Exceptions.contains( cause, e -> e.getMessage().contains( "Connection reset by peer" ) ) ) + { + log.warn( "Fatal error occurred when handling a client connection, " + + "remote peer unexpectedly closed connection: %s", ctx.channel() ); + } + else + { + log.error( String.format( "Fatal error occurred when handling a client connection: %s", ctx.channel() ), + cause ); + } + } + finally + { + close( ctx ); + } } private void close( ChannelHandlerContext ctx ) diff --git a/community/bolt/src/main/java/org/neo4j/bolt/transport/TransportSelectionHandler.java b/community/bolt/src/main/java/org/neo4j/bolt/transport/TransportSelectionHandler.java index a7a3734ca386e..28b3bf9f10d7a 100644 --- a/community/bolt/src/main/java/org/neo4j/bolt/transport/TransportSelectionHandler.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/transport/TransportSelectionHandler.java @@ -35,6 +35,8 @@ import java.util.Map; import java.util.function.BiFunction; +import org.neo4j.helpers.Exceptions; +import org.neo4j.logging.Log; import org.neo4j.logging.LogProvider; import static org.neo4j.bolt.transport.ProtocolChooser.BOLT_MAGIC_PREAMBLE; @@ -49,6 +51,7 @@ public class TransportSelectionHandler extends ByteToMessageDecoder private final boolean encryptionRequired; private final boolean isEncrypted; private final LogProvider logging; + private final Log log; private final Map> protocolVersions; TransportSelectionHandler( SslContext sslCtx, boolean encryptionRequired, boolean isEncrypted, LogProvider logging, @@ -58,6 +61,7 @@ public class TransportSelectionHandler extends ByteToMessageDecoder this.encryptionRequired = encryptionRequired; this.isEncrypted = isEncrypted; this.logging = logging; + this.log = logging.getLog( TransportSelectionHandler.class ); this.protocolVersions = protocolVersions; } @@ -90,6 +94,30 @@ else if ( isBoltPreamble( in ) ) } } + @Override + public void exceptionCaught( ChannelHandlerContext ctx, Throwable cause ) throws Exception + { + try + { + // Netty throws a NativeIoException on connection reset - directly importing that class + // caused a host of linking errors, because it depends on JNI to work. Hence, we just + // test on the message we know we'll get. + if ( Exceptions.contains( cause, e -> e.getMessage().contains( "Connection reset by peer" ) ) ) + { + log.warn( "Fatal error occurred when initialising pipeline, " + + "remote peer unexpectedly closed connection: %s", ctx.channel() ); + } + else + { + log.error( "Fatal error occurred when initialising pipeline: " + ctx.channel(), cause ); + } + } + finally + { + ctx.close(); + } + } + private boolean isBoltPreamble( ByteBuf in ) { return in.getInt( 0 ) == BOLT_MAGIC_PREAMBLE; diff --git a/community/bolt/src/test/java/org/neo4j/bolt/v1/transport/socket/SocketTransportHandlerTest.java b/community/bolt/src/test/java/org/neo4j/bolt/transport/SocketTransportHandlerTest.java similarity index 86% rename from community/bolt/src/test/java/org/neo4j/bolt/v1/transport/socket/SocketTransportHandlerTest.java rename to community/bolt/src/test/java/org/neo4j/bolt/transport/SocketTransportHandlerTest.java index e77c64604a055..6aa1e2b2215cc 100644 --- a/community/bolt/src/test/java/org/neo4j/bolt/v1/transport/socket/SocketTransportHandlerTest.java +++ b/community/bolt/src/test/java/org/neo4j/bolt/transport/SocketTransportHandlerTest.java @@ -17,7 +17,7 @@ * You should have received a copy of the GNU General Public License * along with this program. If not, see . */ -package org.neo4j.bolt.v1.transport.socket; +package org.neo4j.bolt.transport; import io.netty.buffer.ByteBuf; import io.netty.buffer.UnpooledByteBufAllocator; @@ -25,13 +25,11 @@ import io.netty.channel.ChannelHandlerContext; import org.junit.Test; +import java.io.IOException; import java.util.HashMap; import java.util.Map; import java.util.function.BiFunction; -import org.neo4j.bolt.transport.BoltProtocol; -import org.neo4j.bolt.transport.ProtocolChooser; -import org.neo4j.bolt.transport.SocketTransportHandler; import org.neo4j.bolt.v1.runtime.BoltStateMachine; import org.neo4j.bolt.v1.runtime.SynchronousBoltWorker; import org.neo4j.bolt.v1.transport.BoltProtocolV1; @@ -135,14 +133,14 @@ public void logsAndClosesProtocolOnUnexpectedExceptions() throws Throwable // Then verify( machine ).close(); logging.assertExactly( inLog( SocketTransportHandler.class ) - .error( equalTo( "Fatal error occurred when handling a client connection: Oh no!" ), is( cause ) ) ); + .error( equalTo( "Fatal error occurred when handling a client connection: " + ctx.channel() ), is( cause ) ) ); } @Test public void logsAndClosesContextWhenProtocolNotInitializedOnUnexpectedExceptions() throws Throwable { // Given - ChannelHandlerContext context = mock( ChannelHandlerContext.class ); + ChannelHandlerContext context = channelHandlerContextMock(); AssertableLogProvider logging = new AssertableLogProvider(); SocketTransportHandler handler = new SocketTransportHandler( mock( ProtocolChooser.class ), logging ); @@ -153,10 +151,30 @@ public void logsAndClosesContextWhenProtocolNotInitializedOnUnexpectedExceptions // Then verify( context ).close(); logging.assertExactly( inLog( SocketTransportHandler.class ) - .error( equalTo( "Fatal error occurred when handling a client connection: Oh no!" ), + .error( equalTo( "Fatal error occurred when handling a client connection: " + context.channel() ), is( cause ) ) ); } + @Test + public void shouldLogConnectionResetErrorsAtWarningLevelAndClosesContext() throws Exception + { + // Given + ChannelHandlerContext context = channelHandlerContextMock(); + AssertableLogProvider logging = new AssertableLogProvider(); + SocketTransportHandler handler = new SocketTransportHandler( mock( ProtocolChooser.class ), logging ); + + IOException connResetError = new IOException( "Connection reset by peer" ); + + // When + handler.exceptionCaught( context, connResetError ); + + // Then + verify( context ).close(); + logging.assertExactly( inLog( SocketTransportHandler.class ) + .warn( "Fatal error occurred when handling a client connection, " + + "remote peer unexpectedly closed connection: %s", context.channel() ) ); + } + @Test public void shouldInitializeProtocolOnFirstMessage() throws Exception { diff --git a/community/bolt/src/test/java/org/neo4j/bolt/transport/TransportSelectionHandlerTest.java b/community/bolt/src/test/java/org/neo4j/bolt/transport/TransportSelectionHandlerTest.java new file mode 100644 index 0000000000000..ce478e26e6c92 --- /dev/null +++ b/community/bolt/src/test/java/org/neo4j/bolt/transport/TransportSelectionHandlerTest.java @@ -0,0 +1,85 @@ +/* + * Copyright (c) 2002-2018 "Neo4j," + * Neo4j Sweden AB [http://neo4j.com] + * + * This file is part of Neo4j. + * + * Neo4j is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + */ +package org.neo4j.bolt.transport; + +import io.netty.channel.Channel; +import io.netty.channel.ChannelHandlerContext; +import org.junit.Test; + +import java.io.IOException; + +import org.neo4j.logging.AssertableLogProvider; + +import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.sameInstance; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; +import static org.neo4j.logging.AssertableLogProvider.inLog; + +public class TransportSelectionHandlerTest +{ + + @Test + public void shouldLogOnUnexpectedExceptionsAndClosesContext() throws Throwable + { + // Given + ChannelHandlerContext context = channelHandlerContextMock(); + AssertableLogProvider logging = new AssertableLogProvider(); + TransportSelectionHandler handler = new TransportSelectionHandler( null, false, false, logging, null ); + + // When + Throwable cause = new Throwable( "Oh no!" ); + handler.exceptionCaught( context, cause ); + + // Then + verify( context ).close(); + logging.assertExactly( inLog( TransportSelectionHandler.class ) + .error( equalTo( "Fatal error occurred when initialising pipeline: " + context.channel() ), sameInstance( cause ) ) ); + } + + @Test + public void shouldLogConnectionResetErrorsAtWarningLevelAndClosesContext() throws Exception + { + // Given + ChannelHandlerContext context = channelHandlerContextMock(); + AssertableLogProvider logging = new AssertableLogProvider(); + TransportSelectionHandler handler = new TransportSelectionHandler( null, false, false, logging, null ); + + IOException connResetError = new IOException( "Connection reset by peer" ); + + // When + handler.exceptionCaught( context, connResetError ); + + // Then + verify( context ).close(); + logging.assertExactly( inLog( TransportSelectionHandler.class ) + .warn( "Fatal error occurred when initialising pipeline, " + + "remote peer unexpectedly closed connection: %s", context.channel() ) ); + } + + private static ChannelHandlerContext channelHandlerContextMock() + { + Channel channel = mock( Channel.class ); + ChannelHandlerContext context = mock( ChannelHandlerContext.class ); + when( context.channel() ).thenReturn( channel ); + return context; + } +}