tornado Tornado 4.5.3 hangs with openssl 1.1.1 and TLS 1.3

I want to package the Python 3 version of tornado 4.5.3 (the latest 4.x release) for Debian unstable, because salt does not work with tornado 5 yet. See https://github.com/saltstack/salt-jenkins/issues/995 for details.

I updated the test certificate and tweaked the source code to work with Python 3.7:

https://salsa.debian.org/python-team/modules/python-tornado/commit/2c6f99ca6c18d5934a97fb9e6d5d4fa9030efe42
https://salsa.debian.org/python-team/modules/python-tornado/commit/19e541067a64b451ee31b7a3400c48ef61ec082d

Sadly the a few test cases still fail on Debian unstable (they succeed on Ubuntu 18.04):

======================================================================
ERROR: test_inline_read_error (tornado.test.iostream_test.TestIOStreamSSL)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/test/iostream_test.py", line 556, in test_inline_read_error
    server.read_bytes(1, lambda data: None)
  File "/usr/lib/python3.7/unittest/case.py", line 203, in __exit__
    self._raiseFailure("{} not raised".format(exc_name))
  File "/usr/lib/python3.7/unittest/case.py", line 135, in _raiseFailure
    raise self.test_case.failureException(msg)
AssertionError: OSError not raised

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 558, in test_inline_read_error
    server.close()
  File "/tmp/building/package/tornado/iostream.py", line 444, in close
    self.close_fd()
  File "/tmp/building/package/tornado/iostream.py", line 1042, in close_fd
    self.socket.close()
  File "/usr/lib/python3.7/socket.py", line 420, in close
    self._real_close()
  File "/usr/lib/python3.7/ssl.py", line 1108, in _real_close
    super()._real_close()
  File "/usr/lib/python3.7/socket.py", line 414, in _real_close
    _ss.close(self)
OSError: [Errno 9] Bad file descriptor

======================================================================
ERROR: test_inline_read_error (tornado.test.iostream_test.TestIOStreamSSLContext)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/test/iostream_test.py", line 556, in test_inline_read_error
    server.read_bytes(1, lambda data: None)
  File "/usr/lib/python3.7/unittest/case.py", line 203, in __exit__
    self._raiseFailure("{} not raised".format(exc_name))
  File "/usr/lib/python3.7/unittest/case.py", line 135, in _raiseFailure
    raise self.test_case.failureException(msg)
AssertionError: OSError not raised

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 558, in test_inline_read_error
    server.close()
  File "/tmp/building/package/tornado/iostream.py", line 444, in close
    self.close_fd()
  File "/tmp/building/package/tornado/iostream.py", line 1042, in close_fd
    self.socket.close()
  File "/usr/lib/python3.7/socket.py", line 420, in close
    self._real_close()
  File "/usr/lib/python3.7/ssl.py", line 1108, in _real_close
    super()._real_close()
  File "/usr/lib/python3.7/socket.py", line 414, in _real_close
    _ss.close(self)
OSError: [Errno 9] Bad file descriptor

======================================================================
FAIL: test_read_until_close_after_close (tornado.test.iostream_test.TestIOStreamSSL)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 451, in test_read_until_close_after_close
    data = self.wait()
  File "/tmp/building/package/tornado/testing.py", line 336, in wait
    self.__rethrow()
  File "/tmp/building/package/tornado/testing.py", line 272, in __rethrow
    raise_exc_info(failure)
  File "<string>", line 4, in raise_exc_info
  File "/tmp/building/package/tornado/testing.py", line 320, in timeout_func
    timeout)
AssertionError: Async operation timed out after 5 seconds

======================================================================
FAIL: test_streaming_read_until_close_after_close (tornado.test.iostream_test.TestIOStreamSSL)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 481, in test_streaming_read_until_close_after_close
    data = self.wait()
  File "/tmp/building/package/tornado/testing.py", line 336, in wait
    self.__rethrow()
  File "/tmp/building/package/tornado/testing.py", line 272, in __rethrow
    raise_exc_info(failure)
  File "<string>", line 4, in raise_exc_info
  File "/tmp/building/package/tornado/testing.py", line 320, in timeout_func
    timeout)
AssertionError: Async operation timed out after 5 seconds

======================================================================
FAIL: test_write_zero_bytes (tornado.test.iostream_test.TestIOStreamSSL)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 220, in test_write_zero_bytes
    self.wait()
  File "/tmp/building/package/tornado/testing.py", line 336, in wait
    self.__rethrow()
  File "/tmp/building/package/tornado/testing.py", line 272, in __rethrow
    raise_exc_info(failure)
  File "<string>", line 4, in raise_exc_info
  File "/tmp/building/package/tornado/testing.py", line 320, in timeout_func
    timeout)
AssertionError: Async operation timed out after 5 seconds

======================================================================
FAIL: test_read_until_close_after_close (tornado.test.iostream_test.TestIOStreamSSLContext)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 451, in test_read_until_close_after_close
    data = self.wait()
  File "/tmp/building/package/tornado/testing.py", line 336, in wait
    self.__rethrow()
  File "/tmp/building/package/tornado/testing.py", line 272, in __rethrow
    raise_exc_info(failure)
  File "<string>", line 4, in raise_exc_info
  File "/tmp/building/package/tornado/testing.py", line 320, in timeout_func
    timeout)
AssertionError: Async operation timed out after 5 seconds

======================================================================
FAIL: test_streaming_read_until_close_after_close (tornado.test.iostream_test.TestIOStreamSSLContext)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 481, in test_streaming_read_until_close_after_close
    data = self.wait()
  File "/tmp/building/package/tornado/testing.py", line 336, in wait
    self.__rethrow()
  File "/tmp/building/package/tornado/testing.py", line 272, in __rethrow
    raise_exc_info(failure)
  File "<string>", line 4, in raise_exc_info
  File "/tmp/building/package/tornado/testing.py", line 320, in timeout_func
    timeout)
AssertionError: Async operation timed out after 5 seconds

======================================================================
FAIL: test_write_zero_bytes (tornado.test.iostream_test.TestIOStreamSSLContext)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/building/package/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/tmp/building/package/tornado/test/iostream_test.py", line 220, in test_write_zero_bytes
    self.wait()
  File "/tmp/building/package/tornado/testing.py", line 336, in wait
    self.__rethrow()
  File "/tmp/building/package/tornado/testing.py", line 272, in __rethrow
    raise_exc_info(failure)
  File "<string>", line 4, in raise_exc_info
  File "/tmp/building/package/tornado/testing.py", line 320, in timeout_func
    timeout)
AssertionError: Async operation timed out after 5 seconds

You can see the full build and test long here: https://salsa.debian.org/python-team/modules/python-tornado/-/jobs/77766 (you can ignore the test cases that fail with "Cannot assign requested address")

Nov 15 '18 16:11 bdrung

Hmm, I wonder what changed. Debian unstable had a python3-tornado package at version 4.5.3 until March of this year. I assume it passed its tests then.

The test failures are all in SSL tests, and it looks like openssl 1.1 is in use. #2533 reports that openssl 1.1 appears to change exception behavior that might explain this.

Nov 21 '18 04:11 bdarnell

It doesn't look like openssl 1.1 is at fault (at least not alone). I built python 3.6 with openssl 1.1.0e (using this docker script) and the tests of Tornado 4.5.3 didn't break. There's something else going on here.

Nov 21 '18 15:11 bdarnell

Can you test with Python 3.7 again?

Dec 11 '18 12:12 bdrung

Works for me with my macports-based installation of python 3.7 (well, it doesn't completely work, but it doesn't get those "timed out after 5 seconds" errors).

[bdarnell@rowlf ~]$ python3 -m venv /tmp/test
[bdarnell@rowlf ~]$ . /tmp/test/bin/activate
(test) [bdarnell@rowlf ~]$ pip install tornado==4.5.3
Collecting tornado==4.5.3
  Downloading https://files.pythonhosted.org/packages/e3/7b/e29ab3d51c8df66922fea216e2bddfcb6430fb29620e5165b16a216e0d3c/tornado-4.5.3.tar.gz (484kB)
    100% |████████████████████████████████| 491kB 6.6MB/s 
Installing collected packages: tornado
  Running setup.py install for tornado ... done
Successfully installed tornado-4.5.3
You are using pip version 10.0.1, however version 18.1 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.
(test) [bdarnell@rowlf ~]$ python --version
Python 3.7.0
(test) [bdarnell@rowlf ~]$ python -m tornado.test
Traceback (most recent call last):
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/__main__.py", line 14, in <module>
    main()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/runtests.py", line 178, in main
    tornado.testing.main(**kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 732, in main
    unittest.main(defaultTest="all", argv=argv, **kwargs)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/main.py", line 100, in __init__
    self.parseArgs(argv)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/main.py", line 147, in parseArgs
    self.createTests()
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/main.py", line 159, in createTests
    self.module)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 220, in loadTestsFromNames
    suites = [self.loadTestsFromName(name, module) for name in names]
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 220, in <listcomp>
    suites = [self.loadTestsFromName(name, module) for name in names]
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 205, in loadTestsFromName
    test = obj()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/runtests.py", line 63, in all
    return unittest.defaultTestLoader.loadTestsFromNames(TEST_MODULES)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 220, in loadTestsFromNames
    suites = [self.loadTestsFromName(name, module) for name in names]
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 220, in <listcomp>
    suites = [self.loadTestsFromName(name, module) for name in names]
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 154, in loadTestsFromName
    module = __import__(module_name)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/asyncio_test.py", line 49
    ensure_future = asyncio.async
                                ^
SyntaxError: invalid syntax
(test) [bdarnell@rowlf ~]$ rm /tmp/test/lib/python3.7/site-packages/tornado/test/asyncio_test.py 
(test) [bdarnell@rowlf ~]$ python -m tornado.test
............E......................................................EEEEEssssssssssssssssssssssssssssssssss.........................................................................................................E.............................................................................................................................................................................................................................................................................................................................................................................................ss........ssss...................................................................E................................s......................................................................................................................................................................s..........................ssssssssssssss.......s.............................................................s..................................................................................................................................................................s...................................s..........................................................................................................................s........................................................................................
======================================================================
ERROR: asyncio_test (unittest.loader._FailedTest)
----------------------------------------------------------------------
ImportError: Failed to import test module: asyncio_test
Traceback (most recent call last):
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/loader.py", line 154, in loadTestsFromName
    module = __import__(module_name)
ModuleNotFoundError: No module named 'tornado.test.asyncio_test'


======================================================================
ERROR: test_call_with_both (tornado.test.concurrent_test.RunOnExecutorTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 230, in __next__
    return next(self.__wrapped)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 433, in test_call_with_both
    o = Object(io_loop=self.io_loop)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 427, in __init__
    self.__executor = futures.thread.ThreadPoolExecutor(1)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/__init__.py", line 52, in __getattr__
    raise AttributeError(f"module {__name__} has no attribute {name}")
AttributeError: module concurrent.futures has no attribute thread

======================================================================
ERROR: test_call_with_executor (tornado.test.concurrent_test.RunOnExecutorTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 230, in __next__
    return next(self.__wrapped)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 418, in test_call_with_executor
    o = Object(io_loop=self.io_loop)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 412, in __init__
    self.__executor = futures.thread.ThreadPoolExecutor(1)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/__init__.py", line 52, in __getattr__
    raise AttributeError(f"module {__name__} has no attribute {name}")
AttributeError: module concurrent.futures has no attribute thread

======================================================================
ERROR: test_call_with_io_loop (tornado.test.concurrent_test.RunOnExecutorTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 230, in __next__
    return next(self.__wrapped)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 403, in test_call_with_io_loop
    o = Object(io_loop=self.io_loop)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 397, in __init__
    self.executor = futures.thread.ThreadPoolExecutor(1)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/__init__.py", line 52, in __getattr__
    raise AttributeError(f"module {__name__} has no attribute {name}")
AttributeError: module concurrent.futures has no attribute thread

======================================================================
ERROR: test_call_with_no_args (tornado.test.concurrent_test.RunOnExecutorTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 230, in __next__
    return next(self.__wrapped)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 388, in test_call_with_no_args
    o = Object(io_loop=self.io_loop)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 382, in __init__
    self.executor = futures.thread.ThreadPoolExecutor(1)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/__init__.py", line 52, in __getattr__
    raise AttributeError(f"module {__name__} has no attribute {name}")
AttributeError: module concurrent.futures has no attribute thread

======================================================================
ERROR: test_no_calling (tornado.test.concurrent_test.RunOnExecutorTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 230, in __next__
    return next(self.__wrapped)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 373, in test_no_calling
    o = Object(io_loop=self.io_loop)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/concurrent_test.py", line 367, in __init__
    self.executor = futures.thread.ThreadPoolExecutor(1)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/__init__.py", line 52, in __getattr__
    raise AttributeError(f"module {__name__} has no attribute {name}")
AttributeError: module concurrent.futures has no attribute thread

======================================================================
ERROR: test_iterator_async_await (tornado.test.gen_test.WaitIteratorTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 1063, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 210, in throw
    return self.__wrapped.throw(tp, *rest)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/gen_test.py", line 1428, in test_iterator_async_await
    yield namespace['f']()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 1055, in run
    value = future.result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "<string>", line 6, in _wrap_awaitable
  File "<string>", line 6, in f
TypeError: 'async for' received an object from __aiter__ that does not implement __anext__: Future

======================================================================
ERROR: test_async_for (tornado.test.queues_test.QueueGetTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 136, in __call__
    result = self.orig_method(*args, **kwargs)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/testing.py", line 529, in post_coroutine
    timeout=timeout)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/ioloop.py", line 458, in run_sync
    return future_cell[0].result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 1063, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/types.py", line 210, in throw
    return self.__wrapped.throw(tp, *rest)
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/test/queues_test.py", line 174, in test_async_for
    results = yield namespace['f']()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 1055, in run
    value = future.result()
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
  File "/private/tmp/test/lib/python3.7/site-packages/tornado/gen.py", line 307, in wrapper
    yielded = next(result)
  File "<string>", line 6, in _wrap_awaitable
  File "<string>", line 4, in f
TypeError: 'async for' received an object from __aiter__ that does not implement __anext__: Future

----------------------------------------------------------------------
Ran 1395 tests in 12.874s

FAILED (errors=8, skipped=61)
Some tests were skipped because: curl client accepts invalid headers,
needs fix, no testable future imports, non-windows platform, pycares
module not present, pycurl module not present, twisted module not
present
[E 181211 21:10:48 testing:737] FAIL

Dec 12 '18 02:12 bdarnell

The tests succeed on Debian 9 (stretch) and Ubuntu 18.04 (bionic), but they fail on Debian unstable, Ubuntu 18.10 (cosmic) and Ubuntu 19.04 (disco).

Build logs

Ubuntu 18.04 (bionic): https://launchpadlibrarian.net/401407619/buildlog_ubuntu-bionic-amd64.python-tornado4_4.5.3-2~wip20181213+tests~ubuntu18.04.1~ppa1_BUILDING.txt.gz Ubuntu 18.10 (cosmic): https://launchpadlibrarian.net/401407395/buildlog_ubuntu-cosmic-amd64.python-tornado4_4.5.3-2~wip20181213+tests~ubuntu18.10.1~ppa1_BUILDING.txt.gz Ubuntu 19.04 (disco): https://launchpadlibrarian.net/401407363/buildlog_ubuntu-disco-amd64.python-tornado4_4.5.3-2~wip20181213+tests~ubuntu19.04.1~ppa1_BUILDING.txt.gz

Dec 13 '18 20:12 bdrung

OK, I can reproduce this now: it appears that the key is openssl version 1.1.1 (not 1.1.0e, which I had tried, or 1.1.0g in bionic). If I build Python 3.7 with openssl 1.1.1a, the Tornado 4.5.3 tests fail with the 5-second timeout errors. Those errors don't occur with Tornado 5.0.0.

I don't think there were any changes specific to SSL in 5.0, although substantial parts of the relevant code in iostream.py was rewritten for performance. Openssl 1.1.1 claims to be a drop-in replacement for 1.1.0 and I don't see anything obviously relevant in the release notes (it's possible that the offending change was actually in one of the later 1.1.0 releases; I haven't tried 1.1.0h or 1.1.0i)

Dec 15 '18 18:12 bdarnell

Ah wait, there's this:

https://github.com/openssl/openssl/blob/6e94b5aecd619afd25e3dc25902952b1b3194edf/CHANGES#L236

Although that comment specifically refers to blocking IO and it looks like python has set this flag by default for a long time.

Or there's openssl/openssl#7327, suggesting that when TLS 1.3 is used the pattern of messages is different in ways that could potentially confuse socket reading loops. And indeed, adding ctx.maximum_version = ssl.TLSVersion.TLSv1_2 wherever an SSLContext is created eliminates the timeouts.

So I think that's the answer for now: disable TLS 1.3 when using Tornado 4.5 with openssl 1.1.1. Since this is apparently already fixed in 5.0+, I'm not going to personally investigate further on the old release branch (but I'd welcome a patch if there are folks out there who still can't upgrade to 5.x but also can't pin their openssl to a similar vintage).

Dec 15 '18 18:12 bdarnell

It would be great to use TLS 1.3 with tornado 4, because TLS 1.3 would improve the security. Could you point me to the code part where to look for finding the relevant commit to cherry-pick it?

Dec 17 '18 16:12 bdrung

There is one salt state unittest (unit.utils.test_event.TestAsyncEventPublisher.test_event_subscription) that fails with exactly this failure.

Dec 18 '18 18:12 bdrung

Could you point me to the code part where to look for finding the relevant commit to cherry-pick it?

There were a lot of changes to iostream.py between 4.5 and 5.0. It could be an unexpected side effect of some of the new zero-copy fast paths introduced in #2169 or #2251. Or there were some SSL-related changes in #2167 and #2177.

Dec 19 '18 01:12 bdarnell

I tested the two SSL-related changes in #2167 and #2177. They made no difference. Also the patch from #2169 didn't change anything. #2251 does not apply and is not trivially adaptable.

Dec 20 '18 14:12 bdrung

@bdarnell the hangs described are similar to those that also affect perl LWP code. And I am limiting TLS version to v1.2 there as well.

Do you have a patch for v4.5 series that limits the context to TLSv1.2 available somewhere? I think i want to ship that in Ubuntu, as we are about to upgrade OpenSSL to 1.1.1 in 18.04 LTS (bionic).

May 07 '19 17:05 xnox

Also see https://wiki.openssl.org/index.php/TLS1.3#Non-application_data_records for details about it. The perl bug is at https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=914034

May 07 '19 17:05 xnox

Well .maximum_version is only at the moment available in python3's not 2.... I guess I should backport that now.

May 07 '19 17:05 xnox

Do you have a patch for v4.5 series that limits the context to TLSv1.2 available somewhere?

The workaround, as described in https://github.com/tornadoweb/tornado/issues/2536#issuecomment-447589432, is to set ctx.maximum_version = ssl.TLSVersion.TLSv1_2 wherever an SSLContext is created. The trouble is that that may be in application code. I guess IOStream could mutate the supplied context before using it, although that's a little ugly. (Is there a copy method for SSLContexts?)

As far as I know no one's written a proper fix that modifies IOStream to handle the new TLS 1.3 records. I'm not even certain that Tornado 6.0 is safe with TLS 1.3, although it definitely seems to handle it better than 4.5 did.

May 08 '19 02:05 bdarnell

Trolling the cpython (both 2s and 3s) code, I see that it always sets SSL_MODE_AUTO_RETRY and it doesn't expose any APIs to set/clear mode (ie. SSL_CTX_clear_mode and related APIs).

That's a problem. Because it's impossible to implement correctly (without hangs) a blocking IO and correctly handle non-application data records. Cause one would want to clear SSL_MODE_AUTO_RETRY do select/poll/etc, call SSL_read() and correctly go back into select/poll/etc if only non-application data was received (i.e. SSL_ERROR_WANT_READ is returned).

There are more discussions about that at https://bugs.python.org/issue3890 and https://bugs.python.org/issue8222

How does Tornado implement things? Does it have non-blocking I/O implementation? Or is it blocking I/O? or both?

It would be nice to get this fixed properly, as this can be triggered with TLS1.3 more often than other TLS versions. With other TLS versions this issue can be triggered during renegotiation.

May 08 '19 12:05 xnox

How does Tornado implement things? Does it have non-blocking I/O implementation? Or is it blocking I/O? or both?

Tornado always uses non-blocking I/O. And SSL_MODE_AUTO_RETRY is supposed to be a no-op in non-blocking mode.

May 09 '19 00:05 bdarnell

A new openssl landed in Debian, so the current package for tornado is broken: bug

I think it's related to the discussion here... What is the status of this bug?

Mar 23 '20 17:03 SnarkBoojum

The status is the same as it was in this comment: https://github.com/tornadoweb/tornado/issues/2536#issuecomment-490318306

We have a workaround (disabling TLS 1.3) but haven't identified the root cause or a proper fix. Upgrading from Tornado 4.5 to 6.0 appears to make the problem go away, although it's unclear whether this completely fixes the problem or just makes it less frequent.

Apr 25 '20 20:04 bdarnell

Closing this as obsolete since it seems to only apply to Tornado 4.x.

Aug 28 '22 19:08 bdarnell

tornado tornado copied to clipboard

Tornado 4.5.3 hangs with openssl 1.1.1 and TLS 1.3

Build logs

tornado
tornado copied to clipboard