Re: IllegalStateException from LazyChannelPromise (Issue 2174) is back

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

------------------------------------------------------------------------------
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