Title: SSL Handshake never happens even if do_handshake_on_connect=True for server sockets returned from .accept()
Type: Severity: normal
Components: Library Versions: Jython 2.7
Milestone: Jython 2.7.1
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: zyasoft Nosy List: darjus, teeohhem, zyasoft
Priority: high Keywords: patch

Created on 2016-02-08.21:36:08 by teeohhem, last changed 2016-09-06.00:19:29 by zyasoft.

File name Uploaded Description Edit Remove teeohhem, 2016-02-08.21:37:36 teeohhem, 2016-02-08.21:37:49
partial-fix-2462.diff zyasoft, 2016-03-10.00:53:39
fix-2462.diff zyasoft, 2016-03-10.05:15:49
thread-dump-2462.txt darjus, 2016-03-11.00:54:50
msg10730 (view) Author: Tom Alexander (teeohhem) Date: 2016-02-08.21:36:07
Server sockets that are returned from socket.accept() never initiate a handshake, even when do_handshake_on_connect=True. This can be replicated if you have an ssl client that does not handshake on connect (attached a server/ to demonstrate).
msg10731 (view) Author: Tom Alexander (teeohhem) Date: 2016-02-08.21:44:08
This has to do with the fact that sockets returned from .accept() have an underlying socket, which is of the type ChildSocket. in, if said socket is a ChildSocket, the handshake request is purposely ignored.
msg10732 (view) Author: Tom Alexander (teeohhem) Date: 2016-02-08.21:46:14
Note: I also added this JVM flag to see the ssl handshake output
msg10805 (view) Author: Jim Baker (zyasoft) Date: 2016-03-10.00:53:39
Some more work needs to be done, but I've attached a partial fix for this bug that might be worth testing.

Note that test_socket currently fails, without progress, at testSendAll. Most likely this is due to not properly going through the activation barrier. Additionally test_socket_jy has to be revisited now that a ValueError is raised if do_handshake_on_connect=True and the socket is nonblocking, which matches what CPython does.
msg10806 (view) Author: Jim Baker (zyasoft) Date: 2016-03-10.01:18:36
One more thing: I also upgraded the Netty jars to latest to remove the need for RaceFreeSslHandler (I found a bug in that workaround as I was playing with lots of race conditions to solve this problem... easiest to do the upgrade.)
msg10808 (view) Author: Jim Baker (zyasoft) Date: 2016-03-10.05:15:49
Here's a complete fix, which passes all tests.

We still need to write tests that capture what was done in and, ideally with running a CPython client. We can also vary do_handshake_on_connect over (True, False).
msg10814 (view) Author: Darjus Loktevic (darjus) Date: 2016-03-11.00:49:23
Tried the patch. Not sure yet if it is the root cause, but during regrtest jython deadlocked. Investigating.
msg10815 (view) Author: Darjus Loktevic (darjus) Date: 2016-03-11.01:03:59
Also, sporadically (while running test_logging, where the deadlock happened during regrtest).

java.util.concurrent.RejectedExecutionException: event executor terminated
	at io.netty.util.concurrent.SingleThreadEventExecutor.reject(
	at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(
	at io.netty.util.concurrent.SingleThreadEventExecutor.execute(
	at io.netty.util.concurrent.DefaultPromise.execute(
	at io.netty.util.concurrent.DefaultPromise.notifyLateListener(
	at io.netty.util.concurrent.DefaultPromise.addListener(
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(
	at java.lang.reflect.Method.invoke(
	at org.python.core.PyReflectedFunction.__call__(
	at org.python.core.PyReflectedFunction.__call__(
	at org.python.core.PyObject.__call__(
	at org.python.core.PyObject.__call__(
	at org.python.core.PyMethod.__call__(
	at _socket$py.close$89(/Users/darjus/Documents/jython/dist/Lib/
	at _socket$py.call_function(/Users/darjus/Documents/jython/dist/Lib/
	at org.python.core.PyFunction.__call__(
	at org.python.core.PyMethod.__call__(
	at _socket$py.close$127(/Users/darjus/Documents/jython/dist/Lib/
	at _socket$py.call_function(/Users/darjus/Documents/jython/dist/Lib/
	at org.python.core.PyFunction.__call__(
	at org.python.core.PyMethod.__call__(
	at _socket$py.__del__$129(/Users/darjus/Documents/jython/dist/Lib/
	at _socket$py.call_function(/Users/darjus/Documents/jython/dist/Lib/
	at org.python.core.PyFunction.__call__(
	at org.python.core.PyMethod.__call__(
	at org.python.core.PyMethod.__call__(
	at org.python.core.PyObjectDerived.__del_derived__(
	at org.python.core.finalization.FinalizeTrigger.runFinalizer(
	at org.python.core.finalization.FinalizeTrigger.performFinalization(
	at org.python.core.finalization.FinalizeTrigger.finalize(
	at java.lang.System$2.invokeFinalize(
	at java.lang.ref.Finalizer.runFinalizer(
	at java.lang.ref.Finalizer.access$100(
	at java.lang.ref.Finalizer$
msg10816 (view) Author: Jim Baker (zyasoft) Date: 2016-03-11.02:24:57
msg10815 is well known. It mostly occurs in testing, but it's hard to avoid (see and, even if that was in Netty 3)

We might be able to silence, but it's a separable issue from this one.
msg10817 (view) Author: Jim Baker (zyasoft) Date: 2016-03-11.02:37:08
re the thread dump:

Note that it's deadlocking here in PyType.fromClass:

    public static synchronized PyType fromClass(Class<?> c, boolean hardRef) {
        if (class_to_type == null) {
            class_to_type = new MapMaker().weakKeys().weakValues().makeMap();
            addFromClass(PyType.class, null);

with respect to ending a call to a method (initChannel) defined in a Java superclass (ChannelInitializer), which is running in a Netty thread pool.

So I don't think this is a problem in this patch per se, just something that is stressing things in regrtest.

I don't like that singleton setup at all, we should be using the "Initialization On Demand Holder" idiom instead ( Most likely that's the root cause here.
msg10897 (view) Author: Jim Baker (zyasoft) Date: 2016-08-17.04:42:46
Fixed as of
Date User Action Args
2016-09-06 00:19:29zyasoftsetstatus: pending -> closed
2016-08-17 04:42:47zyasoftsetstatus: open -> pending
resolution: accepted -> fixed
messages: + msg10897
2016-03-11 02:37:09zyasoftsetmessages: + msg10817
2016-03-11 02:24:58zyasoftsetmessages: + msg10816
2016-03-11 01:03:59darjussetmessages: + msg10815
2016-03-11 00:54:52darjussetfiles: + thread-dump-2462.txt
2016-03-11 00:49:24darjussetnosy: + darjus
messages: + msg10814
2016-03-10 05:15:53zyasoftsetfiles: + fix-2462.diff
messages: + msg10808
2016-03-10 01:18:37zyasoftsetmessages: + msg10806
2016-03-10 00:53:42zyasoftsetfiles: + partial-fix-2462.diff
keywords: + patch
messages: + msg10805
2016-02-09 01:09:18zyasoftsetpriority: high
assignee: zyasoft
resolution: accepted
nosy: + zyasoft
milestone: Jython 2.7.1
2016-02-08 21:46:15teeohhemsetmessages: + msg10732
2016-02-08 21:44:09teeohhemsetmessages: + msg10731
2016-02-08 21:37:49teeohhemsetfiles: +
2016-02-08 21:37:36teeohhemsetfiles: +
2016-02-08 21:36:08teeohhemcreate