Re: IllegalStateException from LazyChannelPromise (Issue 2174) is back

In my commit https://hg.python.org/jython/rev/63711e6d4d41, I applied a
workaround for the race condition reported by Bob (see the sleep in
https://hg.python.org/jython/rev/63711e6d4d41#l3.22), along with what
additional mapping of Java exceptions to corresponding Python socket or SSL
errors.

The fact that a very short sleep (1ms) seems to resolve this issue
corresponds to what I observed: this bug is a *heisenbug* (!) - it vanishes
completely if I turn on any form of debug logging (
http://en.wikipedia.org/wiki/Heisenbug). Heisenbugs are always fun of
course.

Most likely, the correct long-term solution is to serialize the insertion
of the inbound handler (for recv), as well as send, just so that no data is
being wrapped/unwrapped in the SSLEngine during handshake negotiation. This
roughly corresponds to what we did for latching for server connections. In
both cases, the underlying cause is that SSL socket wrapping - and
unwrapping - can occur at any time in C SSL semantics, in part to support
START_TLS style protocols, which is rather different than what we see in
Java scenarios.

But that's certainly more complicated than the workaround, so we will see
how robust that workaround is first before we escalate to a blocking bug
for the release candidate.

- Jim

On Wed, Mar 4, 2015 at 9:39 PM, Jim Baker <[email protected]> wrote:

> Bob,
>
> Thanks for taking a look at this problem with the requests module. Are you
> accessing publicly accessible URLs by any chance, so we can reproduce? The
> reason I ask is that we have seen socket + SSL code behave differently
> depending on the exact specifics of TCP window framing, SSL handshaking,
> etc.
>
> Another wrinkle is that after we upgraded to to Netty 4.0.25 in
> https://hg.python.org/jython/rev/ab989b7380c3, we have been seeing
> flakiness in SSLSocket.do_handshake when running the Python regression test
> suite. As you can see with this output, it's definitely similar to your
> stack trace:
>
>      [exec] test_ssl
>      [exec] Exception in thread Thread-1206:Traceback (most recent call
> last):
>      [exec]   File
> "/home/jbaker/jythondev/jython27/dist/Lib/threading.py", line 222, in
> _Thread__bootstrap
>      [exec]     self.run()
>      [exec]   File
> "/home/jbaker/jythondev/jython27/dist/Lib/test/test_ssl.py", line 483, in
> run
>      [exec]     elif not self.wrap_conn():
>      [exec]   File
> "/home/jbaker/jythondev/jython27/dist/Lib/test/test_ssl.py", line 439, in
> wrap_conn
>      [exec]     self.sslconn = ssl.wrap_socket(self.sock, server_side=True,
>      [exec]   File
> "/home/jbaker/jythondev/jython27/dist/Lib/test/test_ssl.py", line 439, in
> wrap_conn
>      [exec]     self.sslconn = ssl.wrap_socket(self.sock, server_side=True,
>      [exec]   File "/home/jbaker/jythondev/jython27/dist/Lib/_socket.py",
> line 355, in handle_exception
>      [exec]     return method_or_function(*args, **kwargs)
>      [exec]   File "/home/jbaker/jythondev/jython27/dist/Lib/_socket.py",
> line 355, in handle_exception
>      [exec]     return method_or_function(*args, **kwargs)
>      [exec]   File "/home/jbaker/jythondev/jython27/dist/Lib/ssl.py", line
> 276, in wrap_socket
>      [exec]     return SSLSocket(
>      [exec]   File "/home/jbaker/jythondev/jython27/dist/Lib/ssl.py", line
> 116, in __init__
>      [exec]     self.do_handshake()
>      [exec]   File "/home/jbaker/jythondev/jython27/dist/Lib/ssl.py", line
> 154, in do_handshake
>      [exec]     self._sock._handle_channel_future(handshake, "SSL
> handshake")
>      [exec]   File "/home/jbaker/jythondev/jython27/dist/Lib/_socket.py",
> line 357, in handle_exception
>      [exec]     raise _map_exception(jlx)
>      [exec] error: [Errno 32] Illegal state exception
>
> But note that here it is reporting errno.EPIPE, which I assigned as the
> closest mapping to Java's IllegalStateException error. In contrast, in your
> stack trace, it's the Java exception, so somehow it's not properly getting
> wrapped by the _handle_channel_future method.
>
> Both cases are clearly related, and I believe it's due to not properly
> propagating IllegalStateException errors out as SSLError exceptions, which
> can then allow for a retry by the using code. See
> https://github.com/jimbaker/socket-reboot#ssl-handshaking-and-events on
> the specifics of why SSL handshaking may require retry. I don't think
> there's an additional synchronization required, especially in the case you
> have here, it's syncing on the handshake future.
>
> Because the IllegalStateException is not even being wrapped as a
> socket_error in your reported stacktrace, it's also likely there's a subtly
> different exception path between the requests and test_ssl failures.
>
> - Jim
>
> On Wed, Mar 4, 2015 at 10:27 AM, HADDLETON, Robert W (Bob) <
> [email protected]> wrote:
>
>> I'm using Jython 2.7b4 and the requests module over an SSL connection,
>> and I'm seeing intermittent "Illegal state exception" errors that I managed
>> to trace back to the netty SslHandler, with the same signature documented
>> by issue 2174: http://bugs.jython.org/issue2174
>>
>> The Java stack trace I'm seeing is similar:
>>
>> java.lang.IllegalStateException
>>         at org.python.netty.handler.ssl.SslHandler$LazyChannelPromise.
>> executor(SslHandler.java:1427)
>>         at org.python.netty.util.concurrent.DefaultPromise.
>> checkDeadLock(DefaultPromise.java:388)
>>         at org.python.netty.util.concurrent.DefaultPromise.
>> await(DefaultPromise.java:251)
>>         at org.python.netty.util.concurrent.DefaultPromise.
>> sync(DefaultPromise.java:218)
>>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>>         at sun.reflect.NativeMethodAccessorImpl.invoke(
>> NativeMethodAccessorImpl.java:57)
>>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(
>> DelegatingMethodAccessorImpl.java:43)
>>         at java.lang.reflect.Method.invoke(Method.java:601)
>>         at org.python.core.PyReflectedFunction.__call__(
>> PyReflectedFunction.java:186)
>>         at org.python.core.PyReflectedFunction.__call__(
>> PyReflectedFunction.java:204)
>>         at org.python.core.PyObject.__call__(PyObject.java:461)
>>         at org.python.core.PyObject.__call__(PyObject.java:465)
>>         at org.python.core.PyMethod.__call__(PyMethod.java:126)
>>         at _socket$py._handle_channel_future$70(/opt/jython/Lib/_
>> socket.py:783)
>>         at _socket$py.call_function(/opt/jython/Lib/_socket.py)
>>         at org.python.core.PyTableCode.call(PyTableCode.java:167)
>>         at org.python.core.PyBaseCode.call(PyBaseCode.java:307)
>>         at org.python.core.PyFunction.function___call__(PyFunction.
>> java:471)
>>         at org.python.core.PyFunction.__call__(PyFunction.java:466)
>>         at org.python.core.PyFunction.__call__(PyFunction.java:461)
>>         at org.python.core.PyObject._callextra(PyObject.java:601)
>>         at _socket$py.handle_exception$30(/opt/jython/Lib/_socket.py:370)
>>         at _socket$py.call_function(/opt/jython/Lib/_socket.py)
>>         at org.python.core.PyTableCode.call(PyTableCode.java:167)
>>         at org.python.core.PyBaseCode.call(PyBaseCode.java:307)
>>         at org.python.core.PyBaseCode.call(PyBaseCode.java:161)
>>         at org.python.core.PyFunction.__call__(PyFunction.java:434)
>>         at org.python.core.PyMethod.__call__(PyMethod.java:156)
>>         at ssl$py.do_handshake$8(/opt/jython/Lib/ssl.py:154)
>>
>>
>> Sometimes it works fine 10 times in a row and sometimes it fails 10 times
>> in a row.  Usually it's intermittent with random failures.  It appears to
>> be a timing window or race condition causing the problem.
>>
>> I saw that a workaround for 2174 was provided by patch set
>> http://hg.python.org/jython/rev/f6c9712832d0 and resolved by
>> http://hg.python.org/jython/rev/2c45f75a5406
>>
>> So I re-added the workaround sleep(0.1) call before the sync() call, this
>> time in _socket.py:
>>
>>     def _handle_channel_future(self, future, reason):
>>         # All differences between nonblocking vs blocking with optional
>> timeouts
>>         # is managed by this method.
>>         #
>>         # All sockets can be selected on, regardless of
>> blocking/nonblocking state.
>>         future.addListener(self._notify_selectors)
>>         if self.timeout is None:
>>             log.debug("Syncing on future %s for %s", future, reason,
>> extra={"sock": self})
>> +           time.sleep(0.1)  # FIXME do we need this sleep?
>>             return future.sync()
>>         elif self.timeout:
>>             self._handle_timeout(future.await, reason)
>>             if not future.isSuccess():
>>                 log.debug("Got this failure %s during %s",
>> future.cause(), reason, extra={"sock": self})
>>                 print "Got this failure %s during %s (%s)" %
>> (future.cause(), reason, self)
>>                 raise future.cause()
>>             return future
>>         else:
>>             return future
>>
>> and the problem went away.
>>
>> I don't know much about SSL so I don't know what the real fix should be,
>> but I wanted to at least document the problem and the workaround in case
>> others run into it.
>>
>> Please let me know if there is anything I can do to help debug it
>> further, and also if you want me to create an issue for it.
>>
>> Thanks
>>
>> Bob
>>
>>
>>
>> ------------------------------------------------------------------------------
>> Dive into the World of Parallel Programming The Go Parallel Website,
>> sponsored
>> by Intel and developed in partnership with Slashdot Media, is your hub
>> for all
>> things parallel software development, from weekly thought leadership
>> blogs to
>> news, videos, case studies, tutorials and more. Take a look and join the
>> conversation now. http://goparallel.sourceforge.net/
>> _______________________________________________
>> Jython-users mailing list
>> [email protected]
>> https://lists.sourceforge.net/lists/listinfo/jython-users
>>
>>
>
>
> --
> - Jim
>
> jim.baker@{colorado.edu|python.org|rackspace.com|zyasoft.com}
> twitter.com/jimbaker
> github.com/jimbaker
> bitbucket.com/jimbaker
>



-- 
- Jim

jim.baker@{colorado.edu|python.org|rackspace.com|zyasoft.com}
twitter.com/jimbaker
github.com/jimbaker
bitbucket.com/jimbaker

------------------------------------------------------------------------------
Dive into the World of Parallel Programming The Go Parallel Website, sponsored
by Intel and developed in partnership with Slashdot Media, is your hub for all
things parallel software development, from weekly thought leadership blogs to
news, videos, case studies, tutorials and more. Take a look and join the 
conversation now. http://goparallel.sourceforge.net/

_______________________________________________
Jython-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/jython-users