Repository: netty/netty
Issue: SSLHandler can fail if writes occur before `channelActive` fired
Labels: defect

### Expected behavior

Attempting to write to a channel with an SslHandler when the `channel.writeable.isWritable()` returns true should be allowed.

### Actual behavior

If you attempt to write to a channel with an `SslHandler` prior to `channelActive` being called you can hit an assertion. In particular - if you write to a channel it forces some handshaking (through flush calls) to occur. If the handshake fails - the promise is set to failed. This happens around line `1573` in the `SslHandler.java`.

```
            if (handshakePromise.tryFailure(cause) || alwaysFlushAndClose) {
                SslUtils.handleHandshakeFailure(ctx, cause, notify);
            }
```

I can tell that `channelActive` has not been called because I am in the debugger and the `handshakeStarted` field returns false. However, `ctx.channel().isWriteable()` returns true. So I do not think I am doing anything incorrect.

Eventually netty gets around to calling `channelActive`. This call makes its way down to:

```
    private void handshake(final Promise<Channel> newHandshakePromise) {
        final Promise<Channel> p;
        if (newHandshakePromise != null) {
            final Promise<Channel> oldHandshakePromise = handshakePromise;
            if (!oldHandshakePromise.isDone()) {
                // There's no need to handshake because handshake is in progress already.
                // Merge the new promise into the old one.
                oldHandshakePromise.addListener(new FutureListener<Channel>() {
                    @Override
                    public void operationComplete(Future<Channel> future) throws Exception {
                        if (future.isSuccess()) {
                            newHandshakePromise.setSuccess(future.getNow());
                        } else {
                            newHandshakePromise.setFailure(future.cause());
                        }
                    }
                });
                return;
            }

            handshakePromise = p = newHandshakePromise;
        } else if (engine.getHandshakeStatus() != HandshakeStatus.NOT_HANDSHAKING) {
            // Not all SSLEngine implementations support calling beginHandshake multiple times while a handshake
            // is in progress. See https://github.com/netty/netty/issues/4718.
            return;
        } else {
            // Forced to reuse the old handshake.
            p = handshakePromise;
            assert !p.isDone();
        }

        // Begin handshake.
        final ChannelHandlerContext ctx = this.ctx;
        try {
            engine.beginHandshake();
            wrapNonAppData(ctx, false);
        } catch (Throwable e) {
            setHandshakeFailure(ctx, e);
        } finally {
           forceFlush(ctx);
        }
        applyHandshakeTimeout(p);
    }
```

via:

```
	at io.netty.handler.ssl.SslHandler.handshake(SslHandler.java:1747)
	at io.netty.handler.ssl.SslHandler.startHandshakeProcessing(SslHandler.java:1666)
	at io.netty.handler.ssl.SslHandler.channelActive(SslHandler.java:1807)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:213)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:199)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:192)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelActive(DefaultChannelPipeline.java:1422)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:213)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:199)
	at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:941)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:311)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:341)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:632)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:544)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
	at java.base/java.lang.Thread.run(Thread.java:834)
```

There is an assertion at line 1747 that triggers because the handshake status is set to HandshakeStatus.NOT_HANDSHAKING and the handshake promise is done:

```
        } else if (engine.getHandshakeStatus() != HandshakeStatus.NOT_HANDSHAKING) {
            // Not all SSLEngine implementations support calling beginHandshake multiple times while a handshake
            // is in progress. See https://github.com/netty/netty/issues/4718.
            return;
        } else {
            // Forced to reuse the old handshake.
            p = handshakePromise;
            assert !p.isDone();
        }
```

### Steps to reproduce

I reliably reproduce this by attaching a listener to the netty connect future that initiates an application level write. When the connection is complete we start a write the does enough to cause the handshake to fail before the `channelActive` is called. The reason the handshake is failing is a specific scenario we are testing:

```
javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate)
	at sun.security.ssl.HandshakeContext.<init>(HandshakeContext.java:163) ~[?:?]
	at sun.security.ssl.ClientHandshakeContext.<init>(ClientHandshakeContext.java:95) ~[?:?]
	at sun.security.ssl.TransportContext.kickstart(TransportContext.java:217) ~[?:?]
	at sun.security.ssl.SSLEngineImpl.writeRecord(SSLEngineImpl.java:167) ~[?:?]
	at sun.security.ssl.SSLEngineImpl.wrap(SSLEngineImpl.java:136) ~[?:?]
	at sun.security.ssl.SSLEngineImpl.wrap(SSLEngineImpl.java:116) ~[?:?]
```

Which explains why the handshake is failing so fast.

The stacktrace for the connection callback -> write process is:

```
	at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:1573)
	at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:1542)
	at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:776)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768)
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749)
	at io.netty.handler.logging.LoggingHandler.flush(LoggingHandler.java:265)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768)
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749)
	at io.netty.channel.ChannelDuplexHandler.flush(ChannelDuplexHandler.java:117)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:802)
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814)
	at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794)
	at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1066)
	at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:305)
	at org.elasticsearch.transport.netty4.Netty4TcpChannel.sendMessage(Netty4TcpChannel.java:142)

<Irrelevant Elasticsearch code>

org.elasticsearch.transport.netty4.Netty4TcpChannel.lambda$new$1(Netty4TcpChannel.java:67)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:103)
	at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:84)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:306)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:341)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:632)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:544)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
	at java.base/java.lang.Thread.run(Thread.java:834)
```

### Netty version

Netty 4.1.30-Final

### JVM version (e.g. `java -version`)

openjdk version "11" 2018-09-25

### OS version (e.g. `uname -a`)

Darwin 18.2.0 Darwin Kernel Version 18.2.0

Issue comments:
@tbrooks8 thanks... I will try to find some time to fix this or if you are interested in providing a PR I am happy to review as well :)
I might have time tomorrow to put together a PR. I'll let you know.
@tbrooks8 don't worry I am able to reproduce with a unit test... Seems to only happen on Java11 tho :) Should have a fix soon.
Should be fixed by https://github.com/netty/netty/pull/8486

Pull request review comments:
Could we include the condition under which we can expect this, specifically that the handshake must have already happened/started (and failed?) before the channelActive event was fired.
@bryce-anderson yep.. Let me update the comment

Patch that resolved the issue:
diff --git a/handler/src/main/java/io/netty/handler/ssl/SslHandler.java b/handler/src/main/java/io/netty/handler/ssl/SslHandler.java
index f1de1360bfe..0e3db8d83a8 100644
--- a/handler/src/main/java/io/netty/handler/ssl/SslHandler.java
+++ b/handler/src/main/java/io/netty/handler/ssl/SslHandler.java
@@ -1745,9 +1745,16 @@ public void operationComplete(Future<Channel> future) throws Exception {
             // is in progress. See https://github.com/netty/netty/issues/4718.
             return;
         } else {
+            if (handshakePromise.isDone()) {
+                // If the handshake is done already lets just return directly as there is no need to trigger it again.
+                // This can happen if the handshake(...) was triggered before we called channelActive(...) by a
+                // flush() that was triggered by a ChannelFutureListener that was added to the ChannelFuture returned
+                // from the connect(...) method. In this case we will see the flush() happen before we had a chance to
+                // call fireChannelActive() on the pipeline.
+                return;
+            }
             // Forced to reuse the old handshake.
             p = handshakePromise;
-            assert !p.isDone();
         }
 
         // Begin handshake.


Test patch:
diff --git a/handler/src/test/java/io/netty/handler/ssl/SslHandlerTest.java b/handler/src/test/java/io/netty/handler/ssl/SslHandlerTest.java
index 75375008f78..ab7a63c908c 100644
--- a/handler/src/test/java/io/netty/handler/ssl/SslHandlerTest.java
+++ b/handler/src/test/java/io/netty/handler/ssl/SslHandlerTest.java
@@ -54,6 +54,7 @@
 import io.netty.util.concurrent.Future;
 import io.netty.util.concurrent.FutureListener;
 import io.netty.util.concurrent.Promise;
+import org.hamcrest.CoreMatchers;
 import org.junit.Test;
 
 import java.net.InetSocketAddress;
@@ -63,6 +64,7 @@
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.LinkedBlockingQueue;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicReference;
 
@@ -679,4 +681,77 @@ public void testOutboundClosedAfterChannelInactive() throws Exception {
 
         assertTrue(engine.isOutboundDone());
     }
+
+    @Test(timeout = 10000)
+    public void testHandshakeFailedByWriteBeforeChannelActive() throws Exception {
+        final SslContext sslClientCtx = SslContextBuilder.forClient()
+                                                         .protocols(SslUtils.PROTOCOL_SSL_V3)
+                                                         .trustManager(InsecureTrustManagerFactory.INSTANCE)
+                                                         .sslProvider(SslProvider.JDK).build();
+
+        EventLoopGroup group = new NioEventLoopGroup();
+        Channel sc = null;
+        Channel cc = null;
+        final CountDownLatch activeLatch = new CountDownLatch(1);
+        final AtomicReference<AssertionError> errorRef = new AtomicReference<AssertionError>();
+        final SslHandler sslHandler = sslClientCtx.newHandler(UnpooledByteBufAllocator.DEFAULT);
+        try {
+            sc = new ServerBootstrap()
+                    .group(group)
+                    .channel(NioServerSocketChannel.class)
+                    .childHandler(new ChannelInboundHandlerAdapter())
+                    .bind(new InetSocketAddress(0)).syncUninterruptibly().channel();
+
+            cc = new Bootstrap()
+                    .group(group)
+                    .channel(NioSocketChannel.class)
+                    .handler(new ChannelInitializer<Channel>() {
+                        @Override
+                        protected void initChannel(Channel ch) throws Exception {
+                            ch.pipeline().addLast(sslHandler);
+                            ch.pipeline().addLast(new ChannelInboundHandlerAdapter() {
+                                @Override
+                                public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause)
+                                        throws Exception {
+                                    if (cause instanceof AssertionError) {
+                                        errorRef.set((AssertionError) cause);
+                                    }
+                                }
+
+                                @Override
+                                public void channelActive(ChannelHandlerContext ctx) throws Exception {
+                                    activeLatch.countDown();
+                                }
+                            });
+                        }
+                    }).connect(sc.localAddress()).addListener(new ChannelFutureListener() {
+                        @Override
+                        public void operationComplete(ChannelFuture future) throws Exception {
+                            // Write something to trigger the handshake before fireChannelActive is called.
+                            future.channel().writeAndFlush(wrappedBuffer(new byte [] { 1, 2, 3, 4 }));
+                        }
+                    }).syncUninterruptibly().channel();
+
+            // Ensure there is no AssertionError thrown by having the handshake failed by the writeAndFlush(...) before
+            // channelActive(...) was called. Let's first wait for the activeLatch countdown to happen and after this
+            // check if we saw and AssertionError (even if we timed out waiting).
+            activeLatch.await(5, TimeUnit.SECONDS);
+            AssertionError error = errorRef.get();
+            if (error != null) {
+                throw error;
+            }
+            assertThat(sslHandler.handshakeFuture().await().cause(),
+                       CoreMatchers.<Throwable>instanceOf(SSLException.class));
+        } finally {
+            if (cc != null) {
+                cc.close().syncUninterruptibly();
+            }
+            if (sc != null) {
+                sc.close().syncUninterruptibly();
+            }
+            group.shutdownGracefully();
+
+            ReferenceCountUtil.release(sslClientCtx);
+        }
+    }
 }