knoop
Reputation: 49
Netty ChannelHandler closed when SSL is used
I have a problem using netty in a client/server environment. After setting up the server with
bossGroup = new NioEventLoopGroup();
workerGroup = new NioEventLoopGroup();
try {
serverBootstrap = new ServerBootstrap();
serverBootstrap.group(bossGroup, workerGroup);
serverBootstrap.channel(NioServerSocketChannel.class);
serverBootstrap.childHandler(new ChannelInitializer<SocketChannel>() {
@Override
protected void initChannel(SocketChannel channel) throws Exception {
channel.pipeline().addLast(new ObjectEncoder(), new ObjectDecoder(Integer.MAX_VALUE, ClassResolvers.cacheDisabled(null)), new UserPacketDecoder(serverRev));
channel.pipeline().addLast(new LoggingHandler());
}
});
logger.info(language.getProperty("Server.Info.Netty.PortOpened"));
serverBootstrap.bind(serverPort).sync().channel().closeFuture().sync().channel().closeFuture().sync();
} catch (Exception e) {
logger.error(language.getProperty("Server.Error.Netty.Initialize"), e);
}
with ChannelInboundHandlerAdapter "UserPacketDecoder":
@Override
public void channelRead(ChannelHandlerContext ctx, Object incomingPacket) {
/* Identify */
if(incomingPacket instanceof GetNews){
logger.info("Incoming -> GetNews");
GetNewsAnswer outgoingPacket = new GetNewsAnswer();
ctx.writeAndFlush(outgoingPacket).addListener(ChannelFutureListener.CLOSE);
}
}
@Override
public void exceptionCaught(ChannelHandlerContext ctx, Throwable e) {
logger.error("Error in Netty-Core", e);
ctx.close();
}
The Client connects, sends a request-packet, awaits answer-packet from server and should close the connection by:
workerGroup = new NioEventLoopGroup();
bootstrap = new Bootstrap();
bootstrap.group(workerGroup);
bootstrap.channel(NioSocketChannel.class);
bootstrap.handler(new ChannelInitializer<SocketChannel>() {
@Override
public void initChannel(SocketChannel channel) {
channel.pipeline().addLast(new ObjectEncoder(), new ObjectDecoder(50000000, ClassResolvers.cacheDisabled(null)), new PacketRelay());
channel.pipeline().addLast(new LoggingHandler());
}
});
try {
bootstrap.connect(hostIP, hostPort).sync().channel().closeFuture().sync();
} catch (Exception e) {
logger.error("Error connecting", e);
} finally {
workerGroup.shutdownGracefully();
}
with ChannelInboundHandlerAdapter "PacketRelay":
@Override
public void channelActive(ChannelHandlerContext ctx) {
if( ! (outgoingPacket == null)){
ctx.writeAndFlush(outgoingPacket);
}
}
@Override
public void channelRead(ChannelHandlerContext ctx, Object incomingPacket) {
incomingPacketQueue.add(incomingPacket);
ctx.close();
}
@Override
public void exceptionCaught(ChannelHandlerContext ctx, Throwable e) {
logger.error("Error in Netty-Core", e);
ctx.close();
}
Without encryption everything is working fine! Now i enable SSL (self-signed-certs) on serverside with
System.setProperty("javax.net.ssl.keyStore", ksPath);
System.setProperty("javax.net.ssl.keyStorePassword", ksPW);
System.setProperty("javax.net.ssl.trustStore", tsPath);
System.setProperty("javax.net.ssl.trustStorePassword", tsPW);
SSLContext ctx = null;
try {
ctx = SSLContext.getDefault();
} catch (NoSuchAlgorithmException e) {
e.printStackTrace();
}
final SSLEngine engine = ctx.createSSLEngine();
engine.setUseClientMode(false);
engine.setNeedClientAuth(false); //tried both -> true and false
and
channel.pipeline().addLast("sslHandler", new SslHandler(engine));
as first element in the pipeline. On the client side pretty similar
SSLContext ctx = null;
try {
ctx = SSLContext.getDefault();
} catch (NoSuchAlgorithmException e) {
e.printStackTrace();
}
final SSLEngine engine = ctx.createSSLEngine();
engine.setUseClientMode(true);
and
channel.pipeline().addLast("sslHandler", new SslHandler(engine));
as first element in the pipeline. As you can see i have enabled netty's debugging mode by adding a new LoggingHandler() to pipeline. Also i set
InternalLoggerFactory.setDefaultFactory(new Log4JLoggerFactory());
System.setProperty("javax.net.debug", "ssl");
System.setProperty("ssl.debug", "true");
for additional logging.
The first request from client is processed like expected, but i see an exception on client-side:
nioEventLoopGroup-2-1, WRITE: TLSv1.2 Change Cipher Spec, length = 1
*** Finished
verify_data: { 30, 112, 54, 24, 223, 62, 135, 143, 88, 178, 186, 12 }
***
nioEventLoopGroup-2-1, WRITE: TLSv1.2 Handshake, length = 96
nioEventLoopGroup-2-1, READ: TLSv1.2 Change Cipher Spec, length = 1
nioEventLoopGroup-2-1, READ: TLSv1.2 Handshake, length = 96
*** Finished
verify_data: { 5, 115, 178, 143, 196, 203, 86, 123, 42, 40, 44, 34 }
***
%% Cached client session: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
2018-02-19 16:45:36 DEBUG SslHandler:1435 - [id: 0x0c2c19e6, L:/127.0.0.1:54629 - R:localhost/127.0.0.1:23600] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x0c2c19e6, L:/127.0.0.1:54629 - R:localhost/127.0.0.1:23600] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
nioEventLoopGroup-2-1, WRITE: TLSv1.2 Application Data, length = 129
nioEventLoopGroup-2-1, called closeOutbound()
nioEventLoopGroup-2-1, closeOutboundInternal()
nioEventLoopGroup-2-1, SEND TLSv1.2 ALERT: warning, description = close_notify
nioEventLoopGroup-2-1, WRITE: TLSv1.2 Alert, length = 80
nioEventLoopGroup-2-1, called closeOutbound()
nioEventLoopGroup-2-1, closeOutboundInternal()
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x0c2c19e6, L:/127.0.0.1:54629 ! R:localhost/127.0.0.1:23600] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x0c2c19e6, L:/127.0.0.1:54629 ! R:localhost/127.0.0.1:23600] INACTIVE
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x0c2c19e6, L:/127.0.0.1:54629 ! R:localhost/127.0.0.1:23600] UNREGISTERED
GetNews OK //<-------------------- Answer from server
2018-02-19 16:45:39 DEBUG PoolThreadCache:262 - Freed 13 thread-local buffer(s) from thread: nioEventLoopGroup-2-1
and on the server side
nioEventLoopGroup-3-1, READ: TLSv1.2 Change Cipher Spec, length = 1
nioEventLoopGroup-3-1, READ: TLSv1.2 Handshake, length = 96
*** Finished
verify_data: { 30, 112, 54, 24, 223, 62, 135, 143, 88, 178, 186, 12 }
***
nioEventLoopGroup-3-1, WRITE: TLSv1.2 Change Cipher Spec, length = 1
*** Finished
verify_data: { 5, 115, 178, 143, 196, 203, 86, 123, 42, 40, 44, 34 }
***
nioEventLoopGroup-3-1, WRITE: TLSv1.2 Handshake, length = 96
%% Cached server session: [Session-2, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
2018-02-19 16:45:36 DEBUG SslHandler:1435 - [id: 0x6245c2c5, L:/127.0.0.1:23600 - R:/127.0.0.1:54629] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x6245c2c5, L:/127.0.0.1:23600 - R:/127.0.0.1:54629] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
2018-02-19 16:45:36 INFO UserPacketDecoder:865 - IncomingPacket -> GetNews //<-------------------- Request from client
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 144
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 112
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 144
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 112
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 176
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 160
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 96
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 992
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 96
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 1136
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 112
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 432
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 80
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 64
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 96
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 64
nioEventLoopGroup-3-1, WRITE: TLSv1.1 Application Data, length = 80
nioEventLoopGroup-3-1, READ: TLSv1.1 Application Data, length = 128
nioEventLoopGroup-3-1, WRITE: TLSv1.2 Application Data, length = 122
nioEventLoopGroup-3-1, READ: TLSv1.2 Alert, length = 80
nioEventLoopGroup-3-1, RECV TLSv1.2 ALERT: warning, close_notify
nioEventLoopGroup-3-1, closeInboundInternal()
nioEventLoopGroup-3-1, closeOutboundInternal()
nioEventLoopGroup-3-1, SEND TLSv1.2 ALERT: warning, description = close_notify
nioEventLoopGroup-3-1, WRITE: TLSv1.2 Alert, length = 80
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x6245c2c5, L:/127.0.0.1:23600 - R:/127.0.0.1:54629] USER_EVENT: SslCloseCompletionEvent(SUCCESS)
nioEventLoopGroup-3-1, called closeOutbound()
nioEventLoopGroup-3-1, closeOutboundInternal()
nioEventLoopGroup-3-1, called closeInbound()
nioEventLoopGroup-3-1, closeInboundInternal()
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x6245c2c5, L:/127.0.0.1:23600 ! R:/127.0.0.1:54629] INACTIVE
2018-02-19 16:45:36 DEBUG LoggingHandler:147 - [id: 0x6245c2c5, L:/127.0.0.1:23600 ! R:/127.0.0.1:54629] UNREGISTERED
From now on every connection attempt by a client is registered by the SSLHandler on server, but no Object is transmitted. Client-Output:
nioEventLoopGroup-2-1, WRITE: TLSv1.2 Handshake, length = 203
2018-02-19 16:55:39 DEBUG Recycler:96 - -Dio.netty.recycler.maxCapacityPerThread: 32768
2018-02-19 16:55:39 DEBUG Recycler:97 - -Dio.netty.recycler.maxSharedCapacityFactor: 2
2018-02-19 16:55:39 DEBUG Recycler:98 - -Dio.netty.recycler.linkCapacity: 16
2018-02-19 16:55:39 DEBUG Recycler:99 - -Dio.netty.recycler.ratio: 8
2018-02-19 16:55:39 DEBUG AbstractByteBuf:52 - -Dio.netty.buffer.bytebuf.checkAccessible: true
2018-02-19 16:55:39 DEBUG ResourceLeakDetectorFactory:202 - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@13e73780
2018-02-19 16:55:49 DEBUG LoggingHandler:147 - [id: 0x25b3173b, L:/127.0.0.1:55853 - R:localhost/127.0.0.1:23600] USER_EVENT: SslHandshakeCompletionEvent(javax.net.ssl.SSLException: handshake timed out)
nioEventLoopGroup-2-1, called closeOutbound()
nioEventLoopGroup-2-1, closeOutboundInternal()
nioEventLoopGroup-2-1, SEND TLSv1.2 ALERT: warning, description = close_notify
nioEventLoopGroup-2-1, WRITE: TLSv1.2 Alert, length = 2
nioEventLoopGroup-2-1, called closeInbound()
nioEventLoopGroup-2-1, fatal error: 80: Inbound closed before receiving peer's close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
nioEventLoopGroup-2-1, SEND TLSv1.2 ALERT: fatal, description = internal_error
nioEventLoopGroup-2-1, Exception sending alert: java.io.IOException: writer side was already closed.
2018-02-19 16:55:49 DEBUG LoggingHandler:147 - [id: 0x25b3173b, L:/127.0.0.1:55853 ! R:localhost/127.0.0.1:23600] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
2018-02-19 16:55:49 DEBUG LoggingHandler:147 - [id: 0x25b3173b, L:/127.0.0.1:55853 ! R:localhost/127.0.0.1:23600] INACTIVE
2018-02-19 16:55:49 DEBUG LoggingHandler:147 - [id: 0x25b3173b, L:/127.0.0.1:55853 ! R:localhost/127.0.0.1:23600] UNREGISTERED
2018-02-19 16:55:51 DEBUG PoolThreadCache:262 - Freed 4 thread-local buffer(s) from thread: nioEventLoopGroup-2-1
I can't find the answer... Thanks in advise
Upvotes: 4
Views: 5788
Answers (1)
Eugène Adell
Reputation: 3174
The problem is a connection reuse when the client should close properly, and open a new one. There are 2 proofs of that : the fact it's working for the 1st request only, and the close_notify message sent by the client (and after it, the one sent by the server). After this 1st succeeded transaction, the log shows an SSL handshake timeout which is a normal phenomenon on an SSL connection which is supposed to be closed already.
I don't have enough knowledge for now about netty to give the exact solution, but understanding the cause should help you a lot. In this thread they're giving a way to disable the HTTP Keep-Alive, which is precisely what we want to achieve, by setting the header to Close value. They're fighting against the opposite problem but maybe give us the solution.
Upvotes: 1
Related Questions
- Netty app hangs when I try to close a io.netty.channel.Channel using closeFuture()
- Always failed to close channel (netty) from server-side when the client has been physically killed
- Netty HttpStaticFileServerHandler problem
- Netty SslHandler throws IllegalReferenceCountException
- Netty SimpleChannelInboundHandler close channel
- Netty 4.0.27 HTTP over SSL (as in secure chat sample) fails for multiple clients
- SSL handling failed with netty-all-5.0.0.Alpha2, but was working with netty-all-5.0.0.Alpha1
- Netty ClientBootstrap SSL Handshake Terminates--Channel/ClientBootstrap closing?
- Netty Simple channel handler disconnection is get blocked
- ClosedChannelException observered with netty 3.2.7 and 3.3.1 under load