Repository: netty/netty
Issue: Race condition in SslHandler
Labels: defect

Originally a thread on the mailing list: https://groups.google.com/forum/#!topic/netty/h2ulbfw3uF8

(using Netty 4.0.33, via jython 2.7.1)

I'm wondering if this is a race condition/bug within netty itself or perhaps just a misuse of netty. I'm seeing the following stack trace intermittently when dealing with ssl sockets via jython:

```
java.lang.NullPointerException
    at org.python.netty.handler.ssl.SslHandler.wrapNonAppData(SslHandler.java:585)
    at org.python.netty.handler.ssl.SslHandler.handshake(SslHandler.java:1405)
    at org.python.netty.handler.ssl.SslHandler.channelActive(SslHandler.java:1443)
    at org.python.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:193)
    at org.python.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:179)
    at org.python.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:817)
    at org.python.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:260)
    at org.python.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:290)
    at org.python.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
    at org.python.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at org.python.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at org.python.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at org.python.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at java.lang.Thread.run(Thread.java:745)
```

You can ignore the 'org.python' prefix on the stack trace, thats just because it's running via Jython.

I did some code diving and it looks to me like this is a possible race condition between SslHandler and DefaultChannelPipeline. What I think is happening is this:

In jython, we create an SslHandler object. We then add that handler to our pipeline by calling addFirst:

https://github.com/netty/netty/blob/netty-4.0.33.Final/transport/src/main/java/io/netty/channel/DefaultChannelPipeline.java#L89

Eventually, that ends up calling callHandlerAdded:

https://github.com/netty/netty/blob/netty-4.0.33.Final/transport/src/main/java/io/netty/channel/DefaultChannelPipeline.java#L472

The behavior of callHandlerAdded depends on if you are in the event loop or not. If you are, it immediately calls 'handlerAdded' on the handler, and if not, it submits a task to a threadpool to that eventually calls handlerAdded. This is where I think the race condition is. SslHandler.handlerAdded(...) needs to be called _before_ SslHandler.channelActive(...) is called. Otherwise, you will get the NPE I pasted above becase 'this.ctx' isn't set on the SslHandler object, that's done in the handlerAdded method.


Issue comments:
Fixed in #4706

Corresponding Jython bug: http://bugs.jython.org/issue2401 - we should be able to build shortly, then Nick can see if he reproduce in his environment

Can we also merge this into 4.0?

This will need a more general fix... Looking into it now.

As workaround you can add a task o the EventLoop that will actually add the handler to the pipeline

This is a big tricky... so may take some time.

So I applied the fix from #4706 by subclassing SslHandler and setting ctx in channelActive. That fixed the race condition for me and I don't see any other negative effects, at least so far. Would you recommend against actually utilizing that as a fix until it can be fixed more generally?

@nickmbailey could you try to use netty 4.1 and use this patch ? :

https://github.com/netty/netty/pull/4716

I hope this is a fundamental fix.

I'll have to set up another environment for reproducing the issue, but I'll try to get to that sometime today and verify the issue.

Since we need a fix in Jython and won't be able to upgrade netty to 4.1 in the immediate future, is the approach I described above relatively safe in your opinion?

It is a workaround and should work…

That said once I know it works I will backport the fix to 4.0 as well.

> On 15 Jan 2016, at 18:53, Nick Bailey notifications@github.com wrote:
> 
> I'll have to set up another environment for reproducing the issue, but I'll try to get to that sometime today and verify the issue.
> 
> Since we need a fix in Jython and won't be able to upgrade netty to 4.1 in the immediate future, is the approach I described above relatively safe in your opinion?
> 
> —
> Reply to this email directly or view it on GitHub https://github.com/netty/netty/issues/4705#issuecomment-172033188.

So since I'm hitting the error running through jython on 4.0.33, I can't easily test out this fix.. I tried switching out 4.0.33 with 4.1 but apparently there are big enough changes that it isn't a drop in replacement. 

Can you share the project?

> Am 17.01.2016 um 01:35 schrieb Nick Bailey notifications@github.com:
> 
> So since I'm hitting the error running through jython on 4.0.33, I can't easily test out this fix.. I tried switching out 4.0.33 with 4.1 but apparently there are big enough changes that it isn't a drop in replacement.
> 
> —
> Reply to this email directly or view it on GitHub.

https://bitbucket.org/jython/jython/src

Jython seems to be using Netty: https://bitbucket.org/jython/jython/src/6855fa289d48cf741a3daed2a0bb9c9c87cdf07f/build.xml?at=default&fileviewer=file-view-default#build.xml-181:185

Yeah jython uses netty under the hood. I'm hitting the issue using jython, I have a script that reproduces the issue and I can provide that. I only see the issue on ubuntu 14.04 and not on OSX for whatever reason.

Here's the script I can reproduce with and an example run:

https://gist.github.com/nickmbailey/f80ad965a048c1d4df22

@nickmbailey thanks.. what are the setup steps for jython ?

There isn't any. You can download the jar from here: http://mvnrepository.com/artifact/org.python/jython-standalone/2.7.1b2

I commented on the gist with how to run that script, so once you download that jar and script, that should be all you need.

@nickmbailey got it... will check

@nickmbailey can you give me any pointers how I can use a custom netty jar with jython ?

@nickmbailey @normanmaurer I assume adding it to the classpath first should be ok? Unfortunately I am still seeing issues with 27df0cc6945d43e20d6469ce2bf2fa3a9b8f61dd

```
[johno@habbo-dev-1 netty]$ git log --name-status HEAD^..HEAD
commit 27df0cc6945d43e20d6469ce2bf2fa3a9b8f61dd
Author: Norman Maurer <norman_maurer@apple.com>
Date:   Fri Jan 15 14:23:41 2016 +0100

    [#4705] Ensure ChannelHandler.handlerAdded(...) is always called as first method of the handler

    Motivation:

    If a user adds a ChannelHandler from outside the EventLoop it is possible to get into the situation that handlerAdded(...) is scheduled on the EventLoop and so called after another methods of the ChannelHandler as the EventLoop may a

    Modification:

    - Ensure we always check if the handlerAdded(...) method was called already and if not add the currently needed call to the EventLoop so it will be picked up after handlerAdded(...) was called. This works as if the handler is added t
    - Some cleanup in the DefaultChannelPipeline

    Result:

    Correctly order of method executions of ChannelHandler.

M       transport/src/main/java/io/netty/channel/AbstractChannelHandlerContext.java
M       transport/src/main/java/io/netty/channel/DefaultChannelPipeline.java
```

```
[johno@habbo-dev-1 netty]$ java -cp all/target/netty-all-4.1.0.CR1-SNAPSHOT.jar:jython-standalone-2.7.1b2.jar org.python.util.jython netty-ssl-bug.py
200 OK
0
200 OK
1
200 OK
2
200 OK
3
Traceback (most recent call last):
  File "netty-ssl-bug.py", line 4, in <module>
    conn.request("GET", "/")
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 1001, in request
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 1035, in _send_request
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 997, in endheaders
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 850, in _send_output
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 812, in send
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 1204, in connect
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/_socket.py", line 357, in handle_exception
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/_socket.py", line 357, in handle_exception
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/ssl.py", line 320, in wrap_socket
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/ssl.py", line 147, in __init__
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/ssl.py", line 196, in do_handshake
_socket.SSLError: [Errno 1] Unmapped exception: java.lang.NullPointerException
```

```
[johno@habbo-dev-1 netty]$ java -cp all/target/netty-all-4.1.0.CR1-SNAPSHOT.jar:jython-standalone-2.7.1b2.jar org.python.util.jython netty-ssl-bug.py
200 OK
0
200 OK
1
200 OK
2
200 OK
3
Traceback (most recent call last):
  File "netty-ssl-bug.py", line 4, in <module>
    conn.request("GET", "/")
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 1001, in request
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 1035, in _send_request
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 997, in endheaders
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 850, in _send_output
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 812, in send
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/httplib.py", line 1204, in connect
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/_socket.py", line 357, in handle_exception
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/_socket.py", line 357, in handle_exception
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/ssl.py", line 320, in wrap_socket
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/ssl.py", line 147, in __init__
  File "/home/johno/netty/jython-standalone-2.7.1b2.jar/Lib/ssl.py", line 196, in do_handshake
_socket.SSLError: [Errno 1] Illegal state exception
```

@johnou I don't think so as it seems like they shadow the netty version /cc @nickmbailey 

@normanmaurer ah I see what you mean, it's in the jar as io/netty and org/python/netty.

@normanmaurer looking at their build.xml it's just an uber jar created with jarjar.

I took the pipeline_race branch, built the artifacts, unzipped the all artifact and replaced the netty classes in jython-standalone-2.7.1b2.jar, repeating the same class patching process with a shaded jar created with jarjar (see ant script below).

I can no longer reproduce the errors I pasted above https://github.com/netty/netty/issues/4705#issuecomment-174468261 (ran the script 10 times+).

I uploaded an unofficial patched version of jython to my github branch https://github.com/johnou/netty/commit/b08bcdfef205df4eb43bc8228a6e2e3a91036775

```
[johno@habbo-dev-1 netty]$ unzip all/target/netty-all-4.1.0.CR1-SNAPSHOT.jar
[johno@habbo-dev-1 netty]$ zip -r jython-standalone-2.7.1b2.jar io
.. same with the shaded jar (nb. cd and directory structure must match for patching to work)
```

```
<project name="MyProject" default="dist" basedir=".">
<target name="dist">
    <taskdef name="jarjar" classname="com.tonicsystems.jarjar.JarJarTask"
        classpath="jarjar-1.4.jar"/>
    <jarjar jarfile="netty-all-4.1.0.CR1-shaded.jar">
          <zipfileset src="netty-all-4.1.0.CR1-SNAPSHOT.jar" excludes="META-INF/**"/>
          <rule pattern="io.netty.**" result="org.python.netty.@1"/>
    </jarjar>
</target>
</project>
```

```
[johno@habbo-dev-1 netty]$ java -jar jython-standalone-2.7.1b2-patched.jar netty-ssl-bug.py
200 OK
0
200 OK
1
200 OK
2
200 OK
3
200 OK
4
200 OK
5
200 OK
......
200 OK
94
200 OK
95
200 OK
96
200 OK
97
200 OK
98
200 OK
99
```

Yeah, when I tried to run the pipeline branch previously I copied the updated netty jars into the jython checkout and updated build.xml to use those instead. I think the approach @johnou took should work as well.

@nickmbailey @johnou ok cool. Let me backport the change to 4.0 as well.

@normanmaurer are you actively working on this? If not I have some time to backport your commit to 4.0.

Yep should have it done later today.

> Am 26.01.2016 um 16:11 schrieb Johno Crawford notifications@github.com:
> 
> @normanmaurer are you actively working on this? If not I have some time to backport your commit to 4.0.
> 
> —
> Reply to this email directly or view it on GitHub.

![yourock](https://cloud.githubusercontent.com/assets/323497/12584518/266863d8-c448-11e5-9e76-932373ab5410.jpg)

Fixed


Pull request review comments:

Patch that resolved the issue:
diff --git a/src/main/java/org/jboss/netty/handler/ssl/SslHandler.java b/src/main/java/org/jboss/netty/handler/ssl/SslHandler.java
index 25ff7659f98..b5b1d1d6367 100644
--- a/src/main/java/org/jboss/netty/handler/ssl/SslHandler.java
+++ b/src/main/java/org/jboss/netty/handler/ssl/SslHandler.java
@@ -1005,8 +1005,9 @@ private void wrap(ChannelHandlerContext context, Channel channel) throws SSLExce
             }
 
             if (!success) {
-                IllegalStateException cause =
-                    new IllegalStateException("SSLEngine already closed");
+                Exception cause = channel.isOpen()
+                        ? new SSLException("SSLEngine already closed")
+                        : new ClosedChannelException();
 
                 // Check if we had a pendingWrite in process, if so we need to also notify as otherwise
                 // the ChannelFuture will never get notified


Test patch: